tests: new sending and filtering functions (#3786)

* move log/filter functions into own file

* add ShellCheck global directives

* use new function for tracking logs

The new function, called `_send_email_with_mid`, aligns with suggestions
from @polarethene and is heavily simplified compared to its predecessor
`_send_email_and_get_id`. New helpers will be introduced to filter logs
according to the MID constructed in this function.

* new filters for searching logs with MID

* use new filters (and sending) functions

* add new helper for asserting non-existence of log message

* use new filters in tests

* Apply suggestions from code review

- `_mid` / `MID` => `_msgid` / `MSG_ID`
- Revised documentation / tooltip comments

* Apply suggestions from code review

* fix tests

* use more distinct names for MSG_ID headers

* update `_filter_service_log` to not use `-i -E`

Moreover, I added a function to print the whole mail log. Appropriate
comments were added to this function to indicate that one should only
use this function when necessary.

* adjust helpers to new helper filter

* follow-up of previous commit

* add CHANGELOG entry

* Apply suggestions from code review

* chore: Update OAuth2 to use new log helper

* Apply suggestions from code review

Co-authored-by: Brennan Kinney <5098581+polarathene@users.noreply.github.com>

* added explicit `_regexp` filters for logs

* Apply suggestions from code review

---------

Co-authored-by: Brennan Kinney <5098581+polarathene@users.noreply.github.com>

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 '<virus@external.tld> -> <user1@localhost.localdomain>'"
-  assert_success
+  _service_log_should_contain_string 'mail' 'Blocked INFECTED'
+  assert_output --partial '<virus@external.tld> -> <user1@localhost.localdomain>'
 }

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'
 }

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'
 }

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

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}"
 }

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=<user1@localhost.localdomain>, orig_to=<alias1@localhost.localdomain>' /var/log/mail/mail.log
-  assert_success
+  _service_log_should_contain_string 'mail' 'to=<user1@localhost.localdomain>, orig_to=<alias1@localhost.localdomain>'
   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=<user1~test@localhost.localdomain>, orig_to=<alias1~test@localhost.localdomain>' /var/log/mail/mail.log
-  assert_success
+  _service_log_should_contain_string 'mail' 'to=<user1~test@localhost.localdomain>, orig_to=<alias1~test@localhost.localdomain>'
   assert_output --partial 'status=sent'
   _should_output_number_of_lines 1
 
-  _run_in_container grep 'to=<user1~test@localhost.localdomain>' /var/log/mail/mail.log
-  assert_success
+  _service_log_should_contain_string 'mail' 'to=<user1~test@localhost.localdomain>'
   refute_output --partial 'status=bounced'
 }
 
 @test "delivers mail to existing catchall" {
-  _run_in_container grep 'to=<user1@localhost.localdomain>, orig_to=<wildcard@localdomain2.com>' /var/log/mail/mail.log
-  assert_success
+  _service_log_should_contain_string 'mail' 'to=<user1@localhost.localdomain>, orig_to=<wildcard@localdomain2.com>'
   assert_output --partial 'status=sent'
   _should_output_number_of_lines 1
 }
 
 @test "delivers mail to regexp alias" {
-  _run_in_container grep 'to=<user1@localhost.localdomain>, orig_to=<test123@localhost.localdomain>' /var/log/mail/mail.log
-  assert_success
+  _service_log_should_contain_string 'mail' 'to=<user1@localhost.localdomain>, orig_to=<test123@localhost.localdomain>'
   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 '<nouser@localhost.localdomain>: Recipient address rejected: User unknown in virtual mailbox table' /var/log/mail/mail.log
-  assert_success
+  _service_log_should_contain_string 'mail' '<nouser@localhost.localdomain>: 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 -- '-> <external1@otherdomain.tld>'"
-  assert_success
-  assert_output --partial '<user@external.tld> -> <external1@otherdomain.tld>'
+  _service_log_should_contain_string 'mail' 'Passed CLEAN {RelayedInbound}'
+  run bash -c "grep '<user@external.tld> -> <external1@otherdomain.tld>' <<< '${output}'"
   _should_output_number_of_lines 2
   # assert_output --partial 'external.tld=user@example.test> -> <external1@otherdomain.tld>'
 }
 
 # 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 '<spam@external.tld> -> <user1@localhost.localdomain>'
   _should_output_number_of_lines 1