diff --git a/CHANGELOG.md b/CHANGELOG.md index 35ee73a9..12f07561 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -33,6 +33,11 @@ The most noteworthy change of this release is the update of the container's base - `smtpd_relay_restrictions` (relay policy) is now evaluated after `smtpd_recipient_restrictions` (spam policy). Previously it was evaluated before `smtpd_recipient_restrictions`. Mail to be relayed via DMS must now pass through the spam policy first. - The TLS fingerprint policy has changed the default from MD5 to SHA256 (_DMS does not modify this Postfix parameter, but may affect any user customizations that do_). +### Updates + +- **Tests:** + - Refactored helper methods for sending e-mails with specific `Message-ID` headers and the helpers for retrieving + filtering logs, which together help isolate logs relevant to specific mail when multiple mails have been processed within a single test. ([#3786](https://github.com/docker-mailserver/docker-mailserver/pull/3786)) + ## [v13.3.1](https://github.com/docker-mailserver/docker-mailserver/releases/tag/v13.3.1) ### Fixes diff --git a/test/helper/common.bash b/test/helper/common.bash index 0891bf8c..3c54862c 100644 --- a/test/helper/common.bash +++ b/test/helper/common.bash @@ -18,6 +18,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 "${REPOSITORY_ROOT}/test/helper/log_and_filtering" } __load_bats_helper @@ -228,7 +229,6 @@ function _run_until_success_or_timeout() { # ! ------------------------------------------------------------------- # ? >> Functions to wait until a condition is met - # Wait until a port is ready. # # @param ${1} = port @@ -351,15 +351,6 @@ function _add_mail_account_then_wait_until_ready() { _wait_until_account_maildir_exists "${MAIL_ACCOUNT}" } -# Assert that the number of lines output by a previous command matches the given -# amount (${1}). `lines` is a special BATS variable updated via `run`. -# -# @param ${1} = number of lines that the output should have -function _should_output_number_of_lines() { - # shellcheck disable=SC2154 - assert_equal "${#lines[@]}" "${1:?Number of lines not provided}" -} - # Reloads the postfix service. # # @param ${1} = container name [OPTIONAL] @@ -372,7 +363,6 @@ function _reload_postfix() { _exec_in_container postfix reload } - # Get the IP of the container (${1}). # # @param ${1} = container name [OPTIONAL] @@ -413,62 +403,6 @@ function _should_have_content_in_directory() { assert_success } -# Filters a service's logs (under `/var/log/supervisor/.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:-}") - local FILE="/var/log/supervisor/${SERVICE}.log" - - # Fallback to alternative log location: - [[ -f ${FILE} ]] || FILE="/var/log/mail/${SERVICE}.log" - _run_in_container grep -E "${STRING}" "${FILE}" -} - -# 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_email_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 -E "${MAIL_ID}" /var/log/mail.log -} - # A simple wrapper for netcat (`nc`). This is useful when sending # "raw" e-mails or doing IMAP-related work. # diff --git a/test/helper/log_and_filtering.bash b/test/helper/log_and_filtering.bash new file mode 100644 index 00000000..415a203b --- /dev/null +++ b/test/helper/log_and_filtering.bash @@ -0,0 +1,119 @@ +#!/bin/bash + +# ? ABOUT: Functions defined here aid in working with logs and filtering them. + +# ! ATTENTION: This file is loaded by `common.sh` - do not load it yourself! +# ! ATTENTION: This file requires helper functions from `common.sh`! + +# shellcheck disable=SC2034,SC2155 + +# Assert that the number of lines output by a previous command matches the given amount (${1}). +# `lines` is a special BATS variable updated via `run`. +# +# @param ${1} = number of lines that the output should have +function _should_output_number_of_lines() { + # shellcheck disable=SC2154 + assert_equal "${#lines[@]}" "${1:?Number of lines not provided}" +} + +# Filters a service's logs (under `/var/log/supervisor/.log`) given a specific string. +# +# @param ${1} = service name +# @param ${2} = string to filter by +# @param ... = options given to `grep` (which is used to filter logs) +function _filter_service_log() { + local SERVICE=${1:?Service name must be provided} + local STRING=${2:?String to match must be provided} + shift 2 + + local FILE="/var/log/supervisor/${SERVICE}.log" + # Alternative log location fallback: + [[ -f ${FILE} ]] || FILE="/var/log/mail/${SERVICE}.log" + _run_in_container grep "${@}" "${STRING}" "${FILE}" +} + +# Prints the entirety of the primary mail log. +# Avoid using this method when you could filter more specific log lines with: +# +# 1. _filter_service_log +# 2. _service_log_should[_not]_contain_string +function _show_complete_mail_log() { + _run_in_container cat /var/log/mail/mail.log +} + +# Like `_filter_service_log` but asserts that the string was found. +# +# @param ${1} = service name +# @param ${2} = string to filter by +function _service_log_should_contain_string() { + _filter_service_log "${1}" "${2}" --fixed-strings + assert_success +} + +# Like `_filter_service_log` but asserts that the string was _not_ found. +# +# @param ${1} = service name +# @param ${2} = string to filter by +function _service_log_should_not_contain_string() { + _filter_service_log "${1}" "${2}" --fixed-strings + assert_failure +} + +# Like `_filter_service_log` but asserts that the string was found. +# Uses regular expressions under the hood for pattern matching. +# +# @param ${1} = service name +# @param ${2} = regular expression to filter by +function _service_log_should_contain_string_regexp() { + _filter_service_log "${1}" "${2}" --extended-regexp + assert_success +} + +# Like `_filter_service_log` but asserts that the string was _not_ found. +# Uses regular expressions under the hood for pattern matching. +# +# @param ${1} = service name +# @param ${2} = regular expression to filter by +function _service_log_should_not_contain_string_regexp() { + _filter_service_log "${1}" "${2}" --extended-regexp + assert_failure +} + +# Filters the mail log by the given MSG_ID (Message-ID) parameter, +# printing log lines which include the associated Postfix Queue ID. +# +# @param ${1} = The local-part of a Message-ID header value (``) +function _print_mail_log_of_queue_id_from_msgid() { + # A unique ID Postfix generates for tracking queued mail as it's processed. + # The length can vary (as per the postfix docs). Hence, we use a range to safely capture it. + # https://github.com/docker-mailserver/docker-mailserver/pull/3747#discussion_r1446679671 + local QUEUE_ID_REGEX='[A-Z0-9]{9,12}' + + local MSG_ID=$(__construct_msgid "${1:?The local-part for MSG_ID was not provided}") + shift 1 + + _wait_for_empty_mail_queue_in_container + + QUEUE_ID=$(_exec_in_container tac /var/log/mail.log \ + | grep -E "postfix/cleanup.*: ${QUEUE_ID_REGEX}:.*message-id=${MSG_ID}" \ + | grep -E --only-matching --max-count 1 "${QUEUE_ID_REGEX}" || :) + + # We perform plausibility checks on the IDs. + assert_not_equal "${QUEUE_ID}" '' + run echo "${QUEUE_ID}" + assert_line --regexp "^${QUEUE_ID_REGEX}$" + + # Postfix specific logs: + _filter_service_log 'mail' "${QUEUE_ID}" +} + +# A convenience method that filters for Dovecot specific logs with a `msgid` field that matches the MSG_ID input. +# +# @param ${1} = The local-part of a Message-ID header value (``) +function _print_mail_log_for_msgid() { + local MSG_ID=$(__construct_msgid "${1:?The local-part for MSG_ID was not provided}") + shift 1 + + # Dovecot specific logs: + _filter_service_log 'mail' "msgid=${MSG_ID}" +} diff --git a/test/helper/sending.bash b/test/helper/sending.bash index e18dc1ac..1c5d844a 100644 --- a/test/helper/sending.bash +++ b/test/helper/sending.bash @@ -1,11 +1,13 @@ #!/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`! +# ! ATTENTION: Functions prefixed with `__` are intended for internal use within +# ! this file (or other helpers) only, not in tests. + +# shellcheck disable=SC2034,SC2155 # Sends an e-mail from the container named by the environment variable `CONTAINER_NAME` # to the same or another container. @@ -100,74 +102,35 @@ function _send_email() { return "${RETURN_VALUE}" } -# Like `_send_email` with two major differences: +# Construct the value for a 'Message-ID' header. +# For tests we use only the local-part to identify mail activity in logs. The rest of the value is fixed. # -# 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 takes the name of a variable and inserts IDs one can later -# filter by to check logs. +# A Message-ID header value should be in the form of: `` +# https://en.wikipedia.org/wiki/Message-ID +# https://datatracker.ietf.org/doc/html/rfc5322#section-3.6.4 # -# 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} = The local-part of a Message-ID header value (``) +function __construct_msgid() { + local MSG_ID_LOCALPART=${1:?The local-part for MSG_ID was not provided} + echo "<${MSG_ID_LOCALPART}@dms-tests>" +} + +# Like `_send_email` but adds a "Message-ID: ${1}@dms-tests>" header, +# which allows for filtering logs later. # -# The first argument has to be the name of the variable that the e-mail ID is stored in. -# The second argument **can** be the flag `--expect-rejection`. -# -# - If this flag is supplied, the function does not check whether the whole mail delivery -# transaction was successful. Additionally the queue ID will be retrieved differently. -# - CAUTION: It must still be possible to `grep` for the Message-ID that Postfix -# generated in the mail log; otherwise this function fails. -# -# The rest of the arguments are the same as `_send_email`. -# -# ## Attention -# -# This function assumes `CONTAINER_NAME` to be properly set (to the container -# name the command should be executed in)! -# -# ## 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_email_and_get_id() { - # Export the variable denoted by ${1} so everyone has access - export "${1:?Mail ID must be set for _send_email_and_get_id}" - # Get a "reference" to the content of the variable denoted by ${1} so we can manipulate the content - local -n ID_ENV_VAR_REF=${1:?} - # Prepare the message ID header here because we will shift away ${1} later - local MID="<${1}@dms-tests>" - # Get rid of ${1} so only the arguments for swaks remain +# @param ${1} = The local-part of a Message-ID header value (``) +function _send_email_with_msgid() { + local MSG_ID=$(__construct_msgid "${1:?The local-part for MSG_ID was not provided}") shift 1 - # The unique ID Postfix (and other services) use may be different in length - # on different systems. Hence, we use a range to safely capture it. - local QUEUE_ID_REGEX='[A-Z0-9]{9,12}' - - _wait_for_empty_mail_queue_in_container - _send_email "${@}" --header "Message-Id: ${MID}" - _wait_for_empty_mail_queue_in_container - - # We store Postfix's queue ID first - ID_ENV_VAR_REF=$(_exec_in_container tac /var/log/mail.log \ - | grep -E "postfix/cleanup.*: ${QUEUE_ID_REGEX}:.*message-id=${MID}" \ - | grep -E --only-matching --max-count 1 "${QUEUE_ID_REGEX}" || :) - # But we also requre potential Dovecot sieve output, which requires the mesage ID, - # so we need to provide the message ID too. - ID_ENV_VAR_REF+="|${MID}" - - # Last but not least, we perform plausibility checks on the IDs. - assert_not_equal "${ID_ENV_VAR_REF}" '' - run echo "${ID_ENV_VAR_REF}" - assert_line --regexp "^${QUEUE_ID_REGEX}\|${MID}$" + _send_email "${@}" --header "Message-ID: ${MSG_ID}" } # Send a spam e-mail by utilizing GTUBE. # -# Extra arguments given to this function will be supplied by `_send_email_and_get_id` directly. +# Extra arguments given to this function will be supplied by `_send_email_with_msgid` directly. function _send_spam() { - _send_email_and_get_id MAIL_ID_SPAM "${@}" \ + _send_email_with_msgid 'dms-test-email-spam' "${@}" \ --from 'spam@external.tld' \ --body 'XJS*C4JDBQADN1.NSBN3*2IDNEN*GTUBE-STANDARD-ANTI-UBE-TEST-EMAIL*C.34X' } diff --git a/test/tests/parallel/set1/spam_virus/clamav.bats b/test/tests/parallel/set1/spam_virus/clamav.bats index a916896a..36149edc 100644 --- a/test/tests/parallel/set1/spam_virus/clamav.bats +++ b/test/tests/parallel/set1/spam_virus/clamav.bats @@ -38,8 +38,7 @@ function teardown_file() { _default_teardown ; } } @test 'should be identified by Amavis' { - _run_in_container grep -i 'Found secondary av scanner ClamAV-clamscan' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'Found secondary av scanner ClamAV-clamscan' } @test 'freshclam cron is enabled' { @@ -53,6 +52,6 @@ function teardown_file() { _default_teardown ; } } @test 'rejects virus' { - _run_in_container_bash "grep 'Blocked INFECTED' /var/log/mail/mail.log | grep ' -> '" - assert_success + _service_log_should_contain_string 'mail' 'Blocked INFECTED' + assert_output --partial ' -> ' } diff --git a/test/tests/parallel/set1/spam_virus/disabled_clamav_spamassassin.bats b/test/tests/parallel/set1/spam_virus/disabled_clamav_spamassassin.bats index 1711950f..0f3a7b5b 100644 --- a/test/tests/parallel/set1/spam_virus/disabled_clamav_spamassassin.bats +++ b/test/tests/parallel/set1/spam_virus/disabled_clamav_spamassassin.bats @@ -25,20 +25,18 @@ function setup_file() { function teardown_file() { _default_teardown ; } @test "ClamAV - Amavis integration should not be active" { - _run_in_container grep -i 'Found secondary av scanner ClamAV-clamscan' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'Found secondary av scanner ClamAV-clamscan' } @test "SA - Amavis integration should not be active" { # Wait until Amavis has finished initializing: run _repeat_in_container_until_success_or_timeout 20 "${CONTAINER_NAME}" grep 'Deleting db files in /var/lib/amavis/db' /var/log/mail/mail.log assert_success + # Amavis module for SA should not be loaded (`SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin`): - _run_in_container grep 'scanner SpamAssassin' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'scanner SpamAssassin' } @test "SA - should not have been called" { - _run_in_container grep -i 'connect to /var/run/clamav/clamd.ctl failed' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'connect to /var/run/clamav/clamd.ctl failed' } diff --git a/test/tests/parallel/set1/spam_virus/postscreen.bats b/test/tests/parallel/set1/spam_virus/postscreen.bats index 92333f98..3f93fe9d 100644 --- a/test/tests/parallel/set1/spam_virus/postscreen.bats +++ b/test/tests/parallel/set1/spam_virus/postscreen.bats @@ -56,12 +56,11 @@ function teardown_file() { @test "should successfully pass postscreen and get postfix greeting message (respecting postscreen_greet_wait time)" { # Configure `send_email()` to send from the mail client container (CONTAINER2_NAME) via ENV override, # mail is sent to the DMS server container (CONTAINER1_NAME) via `--server` parameter: - # TODO: Use _send_email_and_get_id when proper resolution of domain names is possible: CONTAINER_NAME=${CONTAINER2_NAME} _send_email --expect-rejection --server "${CONTAINER1_IP}" --port 25 --data 'postscreen.txt' - # CONTAINER_NAME=${CONTAINER2_NAME} _send_email_and_get_id MAIL_ID_POSTSCREEN --server "${CONTAINER1_IP}" --data 'postscreen.txt' - # _print_mail_log_for_id "${MAIL_ID_POSTSCREEN}" + # TODO: Use _send_email_with_msgid when proper resolution of domain names is possible: + # CONTAINER_NAME=${CONTAINER2_NAME} _send_email_with_msgid 'msgid-postscreen' --server "${CONTAINER1_IP}" --data 'postscreen.txt' + # _print_mail_log_for_msgid 'msgid-postscreen' # assert_output --partial "stored mail into mailbox 'INBOX'" - _run_in_container cat /var/log/mail.log - assert_output --partial 'PASS NEW' + _service_log_should_contain_string 'mail' 'PASS NEW' } diff --git a/test/tests/parallel/set1/spam_virus/rspamd_full.bats b/test/tests/parallel/set1/spam_virus/rspamd_full.bats index f66e9231..9e6d6222 100644 --- a/test/tests/parallel/set1/spam_virus/rspamd_full.bats +++ b/test/tests/parallel/set1/spam_virus/rspamd_full.bats @@ -45,16 +45,17 @@ function setup_file() { # We will send 4 emails: # 1. The first one should pass just fine - _send_email_and_get_id MAIL_ID_PASS + _send_email_with_msgid 'rspamd-test-email-pass' # 2. The second one should be rejected (Rspamd-specific GTUBE pattern for rejection) _send_spam --expect-rejection # 3. The third one should be rejected due to a virus (ClamAV EICAR pattern) # shellcheck disable=SC2016 - _send_email_and_get_id MAIL_ID_VIRUS --expect-rejection \ + _send_email_with_msgid 'rspamd-test-email-virus' --expect-rejection \ --body 'X5O!P%@AP[4\PZX54(P^)7CC)7}$EICAR-STANDARD-ANTIVIRUS-TEST-FILE!$H+H*' # 4. The fourth one will receive an added header (Rspamd-specific GTUBE pattern for adding a spam header) # ref: https://rspamd.com/doc/gtube_patterns.html - _send_email_and_get_id MAIL_ID_HEADER --body "YJS*C4JDBQADN1.NSBN3*2IDNEN*GTUBE-STANDARD-ANTI-UBE-TEST-EMAIL*C.34X" + _send_email_with_msgid 'rspamd-test-email-header' \ + --body "YJS*C4JDBQADN1.NSBN3*2IDNEN*GTUBE-STANDARD-ANTI-UBE-TEST-EMAIL*C.34X" _run_in_container cat /var/log/mail.log assert_success @@ -92,7 +93,7 @@ function teardown_file() { _default_teardown ; } } @test 'service log exist and contains proper content' { - _service_log_should_contain_string 'rspamd' 'rspamd .* is loading configuration' + _service_log_should_contain_string_regexp '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 elastic is disabled in the configuration' _service_log_should_contain_string 'rspamd' 'lua module neural is disabled in the configuration' @@ -108,33 +109,40 @@ function teardown_file() { _default_teardown ; } } @test 'normal mail passes fine' { - _service_log_should_contain_string 'rspamd' 'F \(no action\)' + _service_log_should_contain_string 'rspamd' 'F (no action)' - _print_mail_log_for_id "${MAIL_ID_PASS}" + _print_mail_log_for_msgid 'rspamd-test-email-pass' assert_output --partial "stored mail into mailbox 'INBOX'" _count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new/ 1 } @test 'detects and rejects spam' { - _service_log_should_contain_string 'rspamd' 'S \(reject\)' + _service_log_should_contain_string 'rspamd' 'S (reject)' _service_log_should_contain_string 'rspamd' 'reject "Gtube pattern"' - _print_mail_log_for_id "${MAIL_ID_SPAM}" + _print_mail_log_of_queue_id_from_msgid 'dms-test-email-spam' assert_output --partial 'milter-reject' assert_output --partial '5.7.1 Gtube pattern' + _print_mail_log_for_msgid 'dms-test-email-spam' + refute_output --partial "stored mail into mailbox 'INBOX'" + assert_failure + _count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new/ 1 } @test 'detects and rejects virus' { - _service_log_should_contain_string 'rspamd' 'T \(reject\)' + _service_log_should_contain_string 'rspamd' 'T (reject)' _service_log_should_contain_string 'rspamd' 'reject "ClamAV FOUND VIRUS "Eicar-Signature"' - _print_mail_log_for_id "${MAIL_ID_VIRUS}" + _print_mail_log_of_queue_id_from_msgid 'rspamd-test-email-virus' assert_output --partial 'milter-reject' assert_output --partial '5.7.1 ClamAV FOUND VIRUS "Eicar-Signature"' + + _print_mail_log_for_msgid 'dms-test-email-spam' refute_output --partial "stored mail into mailbox 'INBOX'" + assert_failure _count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new/ 1 } @@ -217,10 +225,10 @@ function teardown_file() { _default_teardown ; } _run_in_container_bash '[[ -f /usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin ]]' assert_success - _service_log_should_contain_string 'rspamd' 'S \(add header\)' + _service_log_should_contain_string 'rspamd' 'S (add header)' _service_log_should_contain_string 'rspamd' 'add header "Gtube pattern"' - _print_mail_log_for_id "${MAIL_ID_HEADER}" + _print_mail_log_for_msgid 'rspamd-test-email-header' assert_output --partial "fileinto action: stored mail into mailbox 'Junk'" _count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new/ 1 @@ -265,10 +273,10 @@ function teardown_file() { _default_teardown ; } _nc_wrapper 'nc/rspamd_imap_move_to_junk.txt' '0.0.0.0 143' sleep 1 # wait for the transaction to finish - _run_in_container cat /var/log/mail/mail.log - assert_success - assert_output --partial 'imapsieve: Matched static mailbox rule [1]' - refute_output --partial 'imapsieve: Matched static mailbox rule [2]' + _service_log_should_contain_string 'mail' 'imapsieve: Matched static mailbox rule [1]' + _service_log_should_not_contain_string 'mail' 'imapsieve: Matched static mailbox rule [2]' + + _show_complete_mail_log for LINE in "${LEARN_SPAM_LINES[@]}"; do assert_output --partial "${LINE}" done @@ -279,9 +287,9 @@ function teardown_file() { _default_teardown ; } _nc_wrapper 'nc/rspamd_imap_move_to_inbox.txt' '0.0.0.0 143' sleep 1 # wait for the transaction to finish - _run_in_container cat /var/log/mail/mail.log - assert_success - assert_output --partial 'imapsieve: Matched static mailbox rule [2]' + _service_log_should_contain_string 'mail' 'imapsieve: Matched static mailbox rule [2]' + + _show_complete_mail_log for LINE in "${LEARN_HAM_LINES[@]}"; do assert_output --partial "${LINE}" done diff --git a/test/tests/parallel/set3/mta/dsn.bats b/test/tests/parallel/set3/mta/dsn.bats index 9a65b147..7a6af76c 100644 --- a/test/tests/parallel/set3/mta/dsn.bats +++ b/test/tests/parallel/set3/mta/dsn.bats @@ -54,7 +54,7 @@ function teardown_file() { _nc_wrapper 'emails/nc_raw/dsn/authenticated.txt' '0.0.0.0 587' _wait_for_empty_mail_queue_in_container - _run_in_container grep "${LOG_DSN}" /var/log/mail/mail.log + _filter_service_log 'mail' "${LOG_DSN}" _should_output_number_of_lines 3 } @@ -70,15 +70,14 @@ function teardown_file() { # # Although external requests are discarded, anyone who has requested a DSN # will still receive it, but it will come from the sending mail server, not this one. - _run_in_container grep "${LOG_DSN}" /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' "${LOG_DSN}" # These ports are excluded via master.cf. _nc_wrapper 'emails/nc_raw/dsn/authenticated.txt' '0.0.0.0 465' _nc_wrapper 'emails/nc_raw/dsn/authenticated.txt' '0.0.0.0 587' _wait_for_empty_mail_queue_in_container - _run_in_container grep "${LOG_DSN}" /var/log/mail/mail.log + _service_log_should_contain_string 'mail' "${LOG_DSN}" _should_output_number_of_lines 2 } @@ -92,6 +91,5 @@ function teardown_file() { # DSN requests are rejected regardless of origin. # This is usually a bad idea, as you won't get them either. - _run_in_container grep "${LOG_DSN}" /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' "${LOG_DSN}" } diff --git a/test/tests/parallel/set3/mta/smtp_delivery.bats b/test/tests/parallel/set3/mta/smtp_delivery.bats index e851d94e..d183694b 100644 --- a/test/tests/parallel/set3/mta/smtp_delivery.bats +++ b/test/tests/parallel/set3/mta/smtp_delivery.bats @@ -174,33 +174,28 @@ function _successful() { } @test "delivers mail to existing alias" { - _run_in_container grep 'to=, orig_to=' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'to=, orig_to=' assert_output --partial 'status=sent' _should_output_number_of_lines 1 } @test "delivers mail to existing alias with recipient delimiter" { - _run_in_container grep 'to=, orig_to=' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'to=, orig_to=' assert_output --partial 'status=sent' _should_output_number_of_lines 1 - _run_in_container grep 'to=' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'to=' refute_output --partial 'status=bounced' } @test "delivers mail to existing catchall" { - _run_in_container grep 'to=, orig_to=' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'to=, orig_to=' assert_output --partial 'status=sent' _should_output_number_of_lines 1 } @test "delivers mail to regexp alias" { - _run_in_container grep 'to=, orig_to=' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'to=, orig_to=' assert_output --partial 'status=sent' _should_output_number_of_lines 1 } @@ -227,23 +222,20 @@ function _successful() { } @test "rejects mail to unknown user" { - _run_in_container grep ': Recipient address rejected: User unknown in virtual mailbox table' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' ': Recipient address rejected: User unknown in virtual mailbox table' _should_output_number_of_lines 1 } @test "redirects mail to external aliases" { - _run_in_container_bash "grep 'Passed CLEAN {RelayedInbound}' /var/log/mail/mail.log | grep -- '-> '" - assert_success - assert_output --partial ' -> ' + _service_log_should_contain_string 'mail' 'Passed CLEAN {RelayedInbound}' + run bash -c "grep ' -> ' <<< '${output}'" _should_output_number_of_lines 2 # assert_output --partial 'external.tld=user@example.test> -> ' } # TODO: Add a test covering case SPAMASSASSIN_SPAM_TO_INBOX=1 (default) @test "rejects spam" { - _run_in_container grep 'Blocked SPAM {NoBounceInbound,Quarantined}' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'Blocked SPAM {NoBounceInbound,Quarantined}' assert_output --partial ' -> ' _should_output_number_of_lines 1 diff --git a/test/tests/serial/mail_pop3.bats b/test/tests/serial/mail_pop3.bats index d815e1ee..95ae14aa 100644 --- a/test/tests/serial/mail_pop3.bats +++ b/test/tests/serial/mail_pop3.bats @@ -33,11 +33,10 @@ function teardown_file() { _default_teardown ; } assert_success } -@test '/var/log/mail/mail.log is error-free' { - _run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log - assert_failure - _run_in_container grep ': error:' /var/log/mail/mail.log - assert_failure +# TODO: Remove in favor of a common helper method, as described in vmail-id.bats equivalent test-case +@test 'Mail log is error free' { + _service_log_should_not_contain_string 'mail' 'non-null host address bits in' + _service_log_should_not_contain_string 'mail' ': Error:' } @test '(Manage Sieve) disabled per default' { diff --git a/test/tests/serial/mail_with_oauth2.bats b/test/tests/serial/mail_with_oauth2.bats index 8da87980..c9a02eea 100644 --- a/test/tests/serial/mail_with_oauth2.bats +++ b/test/tests/serial/mail_with_oauth2.bats @@ -110,7 +110,7 @@ function __verify_auth_with_smtp() { function __dovecot_logs_should_verify_success() { # Inspect the relevant Dovecot logs to catch failure / success: - _run_in_container grep 'dovecot:' /var/log/mail.log + _service_log_should_contain_string 'mail' 'dovecot:' refute_output --partial 'oauth2 failed: Introspection failed' assert_output --partial "dovecot: imap-login: Login: user=<${USER_ACCOUNT}>, method=${AUTH_METHOD}" diff --git a/test/tests/serial/tests.bats b/test/tests/serial/tests.bats index a344bd8d..eff151df 100644 --- a/test/tests/serial/tests.bats +++ b/test/tests/serial/tests.bats @@ -182,23 +182,16 @@ function teardown_file() { _default_teardown ; } assert_success } -@test "system: /var/log/mail/mail.log is error free" { - _run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log - assert_failure - _run_in_container grep 'mail system configuration error' /var/log/mail/mail.log - assert_failure - _run_in_container grep ': error:' /var/log/mail/mail.log - assert_failure - _run_in_container grep -i 'is not writable' /var/log/mail/mail.log - assert_failure - _run_in_container grep -i 'permission denied' /var/log/mail/mail.log - assert_failure - _run_in_container grep -i '(!)connect' /var/log/mail/mail.log - assert_failure - _run_in_container grep -i 'using backwards-compatible default setting' /var/log/mail/mail.log - assert_failure - _run_in_container grep -i 'connect to 127.0.0.1:10023: Connection refused' /var/log/mail/mail.log - assert_failure +# TODO: Remove in favor of a common helper method, as described in vmail-id.bats equivalent test-case +@test "system: Mail log is error free" { + _service_log_should_not_contain_string 'mail' 'non-null host address bits in' + _service_log_should_not_contain_string 'mail' 'mail system configuration error' + _service_log_should_not_contain_string 'mail' ': Error:' + _service_log_should_not_contain_string 'mail' 'is not writable' + _service_log_should_not_contain_string 'mail' 'Permission denied' + _service_log_should_not_contain_string 'mail' '(!)connect' + _service_log_should_not_contain_string 'mail' 'using backwards-compatible default setting' + _service_log_should_not_contain_string 'mail' 'connect to 127.0.0.1:10023: Connection refused' } @test "system: /var/log/auth.log is error free" { @@ -212,7 +205,8 @@ function teardown_file() { _default_teardown ; } } @test "system: amavis decoders installed and available" { - _run_in_container_bash "grep -E '.*(Internal decoder|Found decoder) for\s+\..*' /var/log/mail/mail.log*|grep -Eo '(mail|Z|gz|bz2|xz|lzma|lrz|lzo|lz4|rpm|cpio|tar|deb|rar|arj|arc|zoo|doc|cab|tnef|zip|kmz|7z|jar|swf|lha|iso|exe)' | sort | uniq" + _service_log_should_contain_string_regexp 'mail' '.*(Internal decoder|Found decoder) for\s+\..*' + run bash -c "grep -Eo '(mail|Z|gz|bz2|xz|lzma|lrz|lzo|lz4|rpm|cpio|tar|deb|rar|arj|arc|zoo|doc|cab|tnef|zip|kmz|7z|jar|swf|lha|iso|exe)' <<< '${output}' | sort | uniq" assert_success # Support for doc and zoo removed in buster cat <<'EOF' | assert_output diff --git a/test/tests/serial/vmail-id.bats b/test/tests/serial/vmail-id.bats index 2541f4f8..a0fb8537 100644 --- a/test/tests/serial/vmail-id.bats +++ b/test/tests/serial/vmail-id.bats @@ -24,8 +24,7 @@ function teardown_file() { _default_teardown ; } _wait_for_empty_mail_queue_in_container # Should be successfully sent (received) by Postfix: - _run_in_container grep 'to=' /var/log/mail/mail.log - assert_success + _service_log_should_contain_string 'mail' 'to=' assert_output --partial 'status=sent' _should_output_number_of_lines 1 @@ -41,35 +40,28 @@ function teardown_file() { _default_teardown ; } # This test case is shared with tests.bats, but provides context on errors + some minor edits # TODO: Could improve in future with keywords from https://github.com/docker-mailserver/docker-mailserver/pull/3550#issuecomment-1738509088 # Potentially via a helper that allows an optional fixed number of errors to be present if they were intentional -@test '/var/log/mail/mail.log is error free' { +@test 'Mail log is error free' { # Postfix: https://serverfault.com/questions/934703/postfix-451-4-3-0-temporary-lookup-failure - _run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'non-null host address bits in' # Postfix delivery failure: https://github.com/docker-mailserver/docker-mailserver/issues/230 - _run_in_container grep 'mail system configuration error' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'mail system configuration error' # Unknown error source: https://github.com/docker-mailserver/docker-mailserver/pull/85 - _run_in_container grep -i ': error:' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' ': Error:' # Unknown error source: https://github.com/docker-mailserver/docker-mailserver/pull/320 - _run_in_container grep -i 'not writable' /var/log/mail/mail.log - assert_failure - _run_in_container grep -i 'permission denied' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'not writable' + _service_log_should_not_contain_string 'mail' 'Permission denied' # Amavis: https://forum.howtoforge.com/threads/postfix-smtp-error-caused-by-clamav-cant-connect-to-a-unix-socket-var-run-clamav-clamd-ctl.81002/ - _run_in_container grep -i '(!)connect' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' '(!)connect' # Postfix: https://github.com/docker-mailserver/docker-mailserver/pull/2597 - _run_in_container grep -i 'using backwards-compatible default setting' /var/log/mail/mail.log - assert_failure + # Log line match example: https://github.com/docker-mailserver/docker-mailserver/pull/2598#issuecomment-1141176633 + _service_log_should_not_contain_string 'mail' 'using backwards-compatible default setting' # Postgrey: https://github.com/docker-mailserver/docker-mailserver/pull/612#discussion_r117635774 - _run_in_container grep -i 'connect to 127.0.0.1:10023: Connection refused' /var/log/mail/mail.log - assert_failure + _service_log_should_not_contain_string 'mail' 'connect to 127.0.0.1:10023: Connection refused' }