test helpers: add functionality for sending emails (#3026)

* add functionality for filtering mail log by ID

This was not planned, but as @polarthene mentioned in
https://github.com/docker-mailserver/docker-mailserver/pull/3033#issuecomment-1407169569
, filtering the mail log by email ID would be (the only) correct
approach for the Rspamd test (to eliminate race conditions).

I asserted the currect state, and came to the conclusion that this might
(or actually is) something we want in more than one place. So I went
ahead and implemented a solution.

The solution for acquiring the ID is a bit slower because it ensures the
mail queue is empty _before_ and _after_ the mail is sent. This is the
tradeoff one has to make if they want to send multiple emails in one
test file and get their IDs.

I hope you like this approach. I will provide another PR that adjusts
our current tests to use these new functions.

* added note about our helper functions in the docs

I think our work for our custom test framework should be noted in the
docs for newcomers to better understand what they should do.

* adjust Rspamd test to use new helpers for sending

* improve filter helpers further

* add sanity check when acquiring mail ID

* re-add `refute_output` to test which should now work well

docs/content/contributing/tests.md

@@ -26,6 +26,15 @@ The `test/` directory contains multiple directories. Among them is the `bats/` d
 
     We are currently in the process of restructuring all of our tests. Tests will be moved into `test/tests/parallel/` and new tests should be placed there as well.
 
+### Using Our Helper Functions
+
+There are many functions that aid in writing tests. **We urge you to use them!** They will not only ease writing a test but they will also do their best to ensure there are no race conditions or other unwanted side effects. To learn about the functions we provide, you can:
+
+1. look into existing tests for helper functions we already used
+2. look into the `test/helper/` directory which contains all files that can (and will) be loaded in test files
+
+We encourage you to try both of the approaches mentioned above. To make understanding and using the helper functions easy, every function contains detailed documentation comments. Read them carefully!
+
 ### How Are Tests Run?
 
 Tests are split into two categories:

test/helper/common.bash

@@ -17,6 +17,7 @@
 function __load_bats_helper() {
   load "${REPOSITORY_ROOT}/test/test_helper/bats-support/load"
   load "${REPOSITORY_ROOT}/test/test_helper/bats-assert/load"
+  load "${REPOSITORY_ROOT}/test/helper/sending"
 }
 
 __load_bats_helper
@@ -414,5 +415,58 @@ function _count_files_in_directory_in_container()
   _should_output_number_of_lines "${NUMBER_OF_LINES}"
 }
 
+# Filters a service's logs (under `/var/log/supervisor/<SERVICE>.log`) given
+# a specific string.
+#
+# @param ${1} = service name
+# @param ${2} = string to filter by
+# @param ${3} = container name [OPTIONAL]
+#
+# ## Attention
+#
+# The string given to this function is interpreted by `grep -E`, i.e.
+# as a regular expression. In case you use characters that are special
+# in regular expressions, you need to escape them!
+function _filter_service_log() {
+  local SERVICE=${1:?Service name must be provided}
+  local STRING=${2:?String to match must be provided}
+  local CONTAINER_NAME=$(__handle_container_name "${3:-}")
+
+  _run_in_container grep -E "${STRING}" "/var/log/supervisor/${SERVICE}.log"
+}
+
+# Like `_filter_service_log` but asserts that the string was found.
+#
+# @param ${1} = service name
+# @param ${2} = string to filter by
+# @param ${3} = container name [OPTIONAL]
+#
+# ## Attention
+#
+# The string given to this function is interpreted by `grep -E`, i.e.
+# as a regular expression. In case you use characters that are special
+# in regular expressions, you need to escape them!
+function _service_log_should_contain_string() {
+  local SERVICE=${1:?Service name must be provided}
+  local STRING=${2:?String to match must be provided}
+  local CONTAINER_NAME=$(__handle_container_name "${3:-}")
+
+  _filter_service_log "${SERVICE}" "${STRING}"
+  assert_success
+}
+
+# Filters the mail log for lines that belong to a certain email identified
+# by its ID. You can obtain the ID of an email you want to send by using
+# `_send_mail_and_get_id`.
+#
+# @param ${1} = email ID
+# @param ${2} = container name [OPTIONAL]
+function _print_mail_log_for_id() {
+  local MAIL_ID=${1:?Mail ID must be provided}
+  local CONTAINER_NAME=$(__handle_container_name "${2:-}")
+
+  _run_in_container grep -F "${MAIL_ID}" /var/log/mail.log
+}
+
 # ? << Miscellaneous helper functions
 # ! -------------------------------------------------------------------

test/helper/sending.bash

@@ -0,0 +1,68 @@
+#!/bin/bash
+
+# shellcheck disable=SC2034,SC2155
+
+# ? ABOUT: Functions defined here help with sending emails in tests.
+
+# ! ATTENTION: This file is loaded by `common.sh` - do not load it yourself!
+# ! ATTENTION: This file requires helper functions from `common.sh`!
+
+# Sends a mail from localhost (127.0.0.1) via port 25 to the container. To send
+# a custom email, create a file at `test/test-files/email-templates/<TEST FILE>`,
+# and provide `<TEST FILE>` as an argument to this function.
+#
+# @param ${1} = template file (path) name
+# @param ${2} = container name [OPTIONAL]
+#
+# ## Attention
+#
+# This function will just send the email in an "asynchronous" fashion, i.e. it will
+# send the email but it will not make sure the mail queue is empty after the mail
+# has been sent.
+function _send_email() {
+  local TEMPLATE_FILE=${1:?Must provide name of template file}
+  local CONTAINER_NAME=$(__handle_container_name "${2:-}")
+
+  _run_in_container_bash "nc 0.0.0.0 25 < /tmp/docker-mailserver-test/email-templates/${TEMPLATE_FILE}.txt"
+  assert_success
+}
+
+# Like `_send_mail` with two major differences:
+#
+# 1. this function waits for the mail to be processed; there is no asynchronicity
+#    because filtering the logs in a synchronous way is easier and safer!
+# 2. this function prints an ID one can later filter by to check logs
+#
+# No. 2 is especially useful in case you send more than one email in a single
+# test file and need to assert certain log entries for each mail individually.
+#
+# @param ${1} = template file (path) name
+# @param ${2} = container name [OPTIONAL]
+#
+# ## Safety
+#
+# This functions assumes **no concurrent sending of emails to the same container**!
+# If two clients send simultaneously, there is no guarantee the correct ID is
+# chosen. Sending more than one mail at any given point in time with this function
+# is UNDEFINED BEHAVIOR!
+function _send_mail_and_get_id() {
+  local TEMPLATE_FILE=${1:?Must provide name of template file}
+  local CONTAINER_NAME=$(__handle_container_name "${2:-}")
+  local MAIL_ID
+
+  _wait_for_empty_mail_queue_in_container
+  _send_email "${TEMPLATE_FILE}"
+  _wait_for_empty_mail_queue_in_container
+
+  MAIL_ID=$(_exec_in_container tac /var/log/mail.log              \
+    | grep -E -m 1 'postfix/smtpd.*: [A-Z0-9]+: client=localhost' \
+    | grep -E -o '[A-Z0-9]{11}')
+
+  if [[ -z ${MAIL_ID} ]]
+  then
+    echo 'Could not obtain mail ID - aborting!' >&2
+    exit 1
+  fi
+
+  echo "${MAIL_ID}"
+}

test/tests/parallel/set1/spam_virus/rspamd.bats

@@ -1,7 +1,7 @@
 load "${REPOSITORY_ROOT}/test/helper/setup"
 load "${REPOSITORY_ROOT}/test/helper/common"
 
-BATS_TEST_NAME_PREFIX='[rspamd] '
+BATS_TEST_NAME_PREFIX='[Rspamd] '
 CONTAINER_NAME='dms-test_rspamd'
 
 function setup_file() {
@@ -30,14 +30,9 @@ function setup_file() {
 
   # We will send 3 emails: the first one should pass just fine; the second one should
   # be rejected due to spam; the third one should be rejected due to a virus.
-  _run_in_container_bash "nc 0.0.0.0 25 < /tmp/docker-mailserver-test/email-templates/existing-user1.txt"
-  assert_success
-  _run_in_container_bash "nc 0.0.0.0 25 < /tmp/docker-mailserver-test/email-templates/rspamd-spam.txt"
-  assert_success
-  _run_in_container_bash "nc 0.0.0.0 25 < /tmp/docker-mailserver-test/email-templates/rspamd-virus.txt"
-  assert_success
-
-  _wait_for_empty_mail_queue_in_container "${CONTAINER_NAME}"
+  export MAIL_ID1=$(_send_mail_and_get_id 'existing-user1')
+  export MAIL_ID2=$(_send_mail_and_get_id 'rspamd-spam')
+  export MAIL_ID3=$(_send_mail_and_get_id 'rspamd-virus')
 }
 
 function teardown_file() { _default_teardown ; }
@@ -48,49 +43,39 @@ function teardown_file() { _default_teardown ; }
 }
 
 @test "logs exist and contains proper content" {
-  _should_contain_string_rspamd 'rspamd .* is loading configuration'
-  _should_contain_string_rspamd 'lua module clickhouse is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module dkim_signing is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module elastic is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module rbl is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module reputation is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module spamassassin is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module url_redirector is disabled in the configuration'
-  _should_contain_string_rspamd 'lua module metric_exporter is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'rspamd .* is loading configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module clickhouse is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module dkim_signing is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module elastic is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module rbl is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module reputation is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module spamassassin is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module url_redirector is disabled in the configuration'
+  _service_log_should_contain_string 'rspamd' 'lua module metric_exporter is disabled in the configuration'
 }
 
 @test "normal mail passes fine" {
-  _should_contain_string_rspamd 'F (no action)'
+  _service_log_should_contain_string 'rspamd' 'F \(no action\)'
 
-  run docker logs -n 100 "${CONTAINER_NAME}"
-  assert_success
+  _print_mail_log_for_id "${MAIL_ID1}"
   assert_output --partial "stored mail into mailbox 'INBOX'"
 }
 
 @test "detects and rejects spam" {
-  _should_contain_string_rspamd 'S (reject)'
-  _should_contain_string_rspamd 'reject "Gtube pattern"'
+  _service_log_should_contain_string 'rspamd' 'S \(reject\)'
+  _service_log_should_contain_string 'rspamd' 'reject "Gtube pattern"'
 
-  run docker logs -n 100 "${CONTAINER_NAME}"
-  assert_success
+  _print_mail_log_for_id "${MAIL_ID2}"
   assert_output --partial 'milter-reject'
   assert_output --partial '5.7.1 Gtube pattern'
 }
 
 @test "detects and rejects virus" {
-  _should_contain_string_rspamd 'T (reject)'
-  _should_contain_string_rspamd 'reject "ClamAV FOUND VIRUS "Eicar-Signature"'
+  _service_log_should_contain_string 'rspamd' 'T \(reject\)'
+  _service_log_should_contain_string 'rspamd' 'reject "ClamAV FOUND VIRUS "Eicar-Signature"'
 
-  run docker logs -n 8 "${CONTAINER_NAME}"
-  assert_success
+  _print_mail_log_for_id "${MAIL_ID3}"
   assert_output --partial 'milter-reject'
   assert_output --partial '5.7.1 ClamAV FOUND VIRUS "Eicar-Signature"'
   refute_output --partial "stored mail into mailbox 'INBOX'"
 }
-
-function _should_contain_string_rspamd() {
-  local STRING=${1:?No string provided to _should_contain_string_rspamd}
-
-  _run_in_container grep -q "${STRING}" /var/log/supervisor/rspamd.log
-  assert_success
-}