tests(refactor): Adjust mail_changedetector + change detection helpers

[polarathene]

Description

• Refactored mail_changedetector to the new test conventions. Logic remains roughly the same, just easier to grok.
• tls_letsencrypt test had some improvements as a result of this.
• setup-cli test used the original setup helper methods, no change to logic there, just fully adapted to helper/setup.bash and adjusted the test case prefix.
• Change detection helper was refactored. A generic log watching method is used, with support for waiting on an expected count.
  • This was necessary as the mail_changedetector test as two concurrent change events happening, where one may have already processed before you can wait on it. Another test case cannot wait on completion, but instead needs to wait on a change detection starting.
• Change detection helpers now live in a separate file. Not sure how useful that is. All tests that use it are migrated to the helper/common.bash methods. This also allowed for dropping the helpers from test_helper/common.bash, as well as the related methods in that file that now exist in helper/setup.bash.
• We no longer use the previous change detection helper method (Oct 2020 for tests.bats). Thus I've removed that method and the related test_helper.bats cases for it. Existing methods should have fairly decent coverage in mail_changedetector using it against the actual changedetector service, and not just watching for a checksum change separately (which is not that useful for us).

---

This refactor removes the need to depend on sleep, shaving off approx 2 mins of time (potentially a bit less until some additional PRs are merged).

I've staged out changes across commits (with associated commit messages) that should make the review of diffs a bit more easier if it helps 😅

The original mail_changedetector test was implemented in Sep 2021. It was added with a focus on testing the locking script with multiple containers sharing a network volume for config (/tmp/docker-mailserver).

---

I have taken extra care with the changes done here (over several days). I ran repeat test runs, along with some other changes I'm pushing as separate PRs to ensure that the change detection tests remain consistent / reliable.

I was quite thorough with the refactor (easier to follow through the staged commit diffs). I am confident in it and the revised change detection helper.

Type of change

• Improvement (non-breaking change that does improve existing functionality)

Checklist:

• My code follows the style guidelines of this project
• I have performed a self-review of my own code
• I have commented my code, particularly in hard-to-understand areas
• If necessary I have added tests that prove my fix is effective or that my feature works
• New and existing unit tests pass locally with my changes

[polarathene]

I haven't compared, but casper had suggested a different approach than polling like I'm doing here.

Suggested change

	repeat_until_success_or_timeout 20 __has_expected_count
	timeout 60 docker exec "${CONTAINER_NAME}" bash -c "tail -F '${MATCH_IN_LOG}' | grep --max-count ${EXPECTED_COUNT} '${MATCH_CONTENT}'"

That will take a stream of the log and exit once the result count is matched. It needed to use bash -c, even if using docker logs --follow for the input as I found it'd hang otherwise (presumably something to do with stdin not closing?)

[casperklein]

I cannot reproduce the hanging. I tried this:

# exit as soon as the keyword "spawned" appears
docker logs -n0 -f mail | grep -q spawned

Then in another session:

docker exec mail supervisorctl restart update-check

PS: The container must be running with SUPERVISOR_LOGLEVEL=info I think, that this example works.

[polarathene]

I was able to reproduce on current master the same issue. I tested with replacing this:

docker-mailserver/test/tests/parallel/set1/spam_virus/spam_junk_folder.bats

Lines 33 to 35 in 1650cdf

	# message will be added to a queue with varying delay until amavis receives it
	run repeat_until_success_or_timeout 60 bash -c "docker logs ${CONTAINER_NAME} | grep 'Passed SPAM {RelayedTaggedInbound,Quarantined}'"
	assert_success

Reproduction

# Passes before timing out:
timeout 20 docker exec "${CONTAINER_NAME}" bash -c "tail -F /var/log/mail/mail.log | grep --max-count 1 'Passed SPAM'"
# Same result here:
docker exec "${CONTAINER_NAME}" bash -c "timeout 20 tail -F /var/log/mail/mail.log | grep --max-count 1 'Passed SPAM'"
# Times out with failure, and due to -q has no output:
timeout 20 bash -c "docker logs --follow ${CONTAINER_NAME} | grep -q 'Passed SPAM'"
# Times out with failure, but correctly shows output of requested max lines (even if there were more present)
timeout 20 bash -c "docker logs --follow ${CONTAINER_NAME} | grep --max-count 1 'Passed SPAM'"
# Times out but **passes** (docker logs was stopped by timeout, grep was successful)
timeout 20 docker logs --follow "${CONTAINER_NAME}" | grep --max-count 1 'Passed SPAM'

function _passed_spam() {
  # Any method from above here
}

# Replace as 2nd assert in either test case of `tests/parallel/set1/spam_virus/spam_junk_folder.bats:
run _passed_spam
assert_success

---

Perhaps it's something different with our environments or how docker logs --follow works on our machines? For me, given the above observations, it doesn't seem like the stream is closed?

I had also verified by running the same command in another terminal session directly while the test was running. It would find the match and output it, but not exit until the timeout was reached.

I've had a similar experience with -q (not as nice as --max-count), where either option was working at least for decoder as the value to match when the container was starting up (I could not reproduce with Passed SPAM for some reason..). I could repeat the command in the terminal several times and it'll exit quickly with either option successful. However a few seconds after that and it would fail, even though the logs command would clearly show the lines 🤷‍♂️

Clearly something is iffy there, at least on my end :\

UPDATE: My grep command is the problem.

[polarathene]

I swapped grep for rg (ripgrep), and now it works as you'd expect...

So something wrong with my grep command I guess? 🤷‍♂️

---

I'd rather avoid the -q or --max-count approach, at least with a local grep call, as it seems that's where the problem is. The containers grep was working fine with tail, which would be ok as it avoids false positives when I run tests locally.

We could add ripgrep as a dependency for testing like we do with jq I suppose? (but then CI may need to grab/install it each time, unless it already provides that like it does jq)

[casperklein]

So something wrong with my grep command I guess? 🤷‍♂️

yes 😄

docker logs ${CONTAINER_NAME} | grep 'Passed SPAM {RelayedTaggedInbound,Quarantined}'"

When you don't pass -q or --max-count 1, grep runs infinitly. Why should it stop?

If you only need to now, if a keyword was found, go with -q. If you need the output to parse further or make assertions, go with --max-count 1.

[polarathene]

When you don't pass -q or --max-count 1, grep runs infinitly. Why should it stop?

You're referring to the current version in master I referenced? That is not using --follow, so it does not run infinitely. The attempts I tried can be found in the collapsed "> Reproduction" section.

I collapsed it after responding with an update about my local grep being the problem. I understand the reason for -q or --max-count 1, but only if we're using grep within the container (doesn't make sense for docker logs --follow due to that), as for whatever reason my local grep is misbehaving which would be problematic for me running tests locally 😅 (something I've been doing quite frequently lately)

If we're to use either option with docker logs --follow, then I'd need to know why my grep is broken and how to fix it, or add ripgrep as a dependency for tests.

[casperklein]

The attempts I tried can be found in the collapsed "> Reproduction" section.

Thanks, I overlooked that.

BTW: Are you running the tests on debian/ubuntu?

[polarathene]

Are you running the tests on debian/ubuntu?

EndeavourOS (ArchLinux based)

[casperklein]

Depending on how much more time you want to invest, you may try the "grep" binary from debian:

docker create --name grep debian
docker cp grep:/bin/grep .
docker rm grep

I am wondering, that such a basic tool behaves differently between linux distros.

PS: If we are ever in doubt, we should stick with debian based distros supported for testing (because CI is also running on ubuntu).

[georglauterbach]

Looks really good to me! Just some very minor stylistic changes :)

[georglauterbach]

Got an upcoming PR about changes to test/helper/*.sh which should be merged after this and #3004. The PR will adjust mail_privacy.bats and refactor test/helper/*.sh, i.e. apply our style guides and documentation. Just FYI so we avoid large merge conflicts.

UPDATE: branch pushed, name = tests/more-reqrites-1

[polarathene]

UPDATE: branch pushed, name = tests/more-reqrites-1

I see you've got a nice clean separation of commits so that's fine if you want to bundle mail_privacy.bats into that 👍

If you're planning to rework more tests into that branch, maybe use a separate branch for the broader change with renaming; then after that's merged cherry-pick the extra commits into a new branch / PR? 😅

I'm not bothered either way, but it is preferable to separate out diff noise (like the method renaming interfering with a different scope of changes) from the "review changes" view when possible :)

---

Small heads-up, there will be some conflicts for either you or me to deal with as I'm presently putting together a test file that collects all the process checking and restarts into a single file. That affects some of the tests your function rename touches as it deletes the test cases from those parallel set tests.

It affects the following tests presently:

• parallel/set1/spam_virus/clamav.bats
• parallel/set1/spam_virus/fail2ban.bats
• parallel/set1/spam_virus/disabled_clamav_spamassassin.bats
• parallel/set1/spam_virus/postgrey_enabled.bats
• serial/mail_fetchmail.bats
• serial/mail_smtponly.bats
• serial/mail_with_ldap.bats
• serial/mail_with_postgrey_disabled_by_default.bats
• serial/tests.bats

It may also remove the need for check_if_process_is_running() helper, or I'll be modifying that method.

[casperklein]

Suggested change

	EXPECTED_COUNT=$(bc <<< "$(__get_count) + 1")
	EXPECTED_COUNT=$(( $(__get_count) + 1 ))

[polarathene]

Oh weird, I remember having trouble getting that to work at the time and had ended up with the bc <<< version 😅

That works well, thanks! 😁

---

EDIT: Broke smtp-delivery.bats where an implicit count is used.

[casperklein]

No glue why this doesn't work and the tests fail 🤷

[casperklein]

Alright, I found the root cause.

Because, set -e is in use, the $(()) operation fails, because the called function __get_count returns exit code 1, when there are 0 matches.

As 0 matches is a valid return value (for us), this should be fixed by appending || true:

docker exec "${CONTAINER_NAME}" grep --count "${MATCH_CONTENT}" "${MATCH_IN_LOG}" || true.

After that, EXPECTED_COUNT=$(( $(__get_count) + 1 )) works fine.

[georglauterbach]

I'll be resolving the conflicts, don't worry! I'll be using a train ride tomorrow, so I hope we can merge this until tomorrow evening - that'd be nice :D

[polarathene]

There was a failure related to the change detection wait method in parallel set3 smtp-delivery. Not sure if it's related to the last change suggestion. I re-ran the jobs and it seems to have failed that test again.

[polarathene]

Confirmed. The mail_changedetector test didn't error as that conditional path in the helper method isn't covered by it. When no explicit expected count is set, which is the case for usage elsewhere, it should set the +1 of current count.

The change @casperklein proposed caused instant failure during setup_file() when called. Reverted to how it was before which works correctly.

[georglauterbach]

Can be merged. I'll be placing a new PR then for the refactored helper ;)

[casperklein]

There was a failure related to the change detection wait method in parallel set3 smtp-delivery.

How to run only the set3 tests? This doesn't work:

make tests/parallel/set3

parallel: invalid option -- '-'
parallel [OPTIONS] command -- arguments
        for each argument, run command with argument, in parallel
parallel [OPTIONS] -- commands
        run specified commands in parallel
   bats warning: Executed 0 instead of expected 31 tests

31 tests, 0 failures, 31 not run in 1 seconds

make: *** [Makefile:50: tests/parallel/set3] Error 1

Edit: For now, I use test/bats/bin/bats -T test/tests/parallel/set3/smtp-delivery.bats

[georglauterbach]

Did you run make generate-accounts before? Running the command make clean generate-accounts tests/parallel/setX works for me.

[casperklein]

I did run just "make" to create all necessary stuff. Then tests failed and I wanted to re-run only set3.

Same with your example:

make clean generate-accounts tests/parallel/set3
parallel: invalid option -- '-'
parallel [OPTIONS] command -- arguments
        for each argument, run command with argument, in parallel
parallel [OPTIONS] -- commands
        run specified commands in parallel
   bats warning: Executed 0 instead of expected 31 tests

31 tests, 0 failures, 31 not run in 1 seconds

make: *** [Makefile:50: tests/parallel/set3] Error 1

Better solution found.

[georglauterbach]

I will have a look later at this too.

[georglauterbach]

Tested it again; runs smoothly on my system (Ubuntu 22.04 LTS). Packages are up-to-date.

EDIT: Does make clean generate-accounts test/smtp-delivery work?

[casperklein]

EDIT: Does make clean generate-accounts test/smtp-delivery work?

yes

[polarathene]

Ok, missed my opportunity to merge with both approvals it seems 😛

I've added the solution @casperklein requested, hope this is good for merging now 👍