scripts: refactored check-for-changes.sh (#2498)

* refactored `check-for-changes.sh`

I refactored `check-for-changes.sh` and used the new log. `_notify` can
therefore be deleted as it is used no more.
I opted to source `/etc/dms-settings` as a whole to
future-proof the script. When the DNS adjustments PRs (that do not exist
by now but will exit in the future) are done, we can then remove
`_obtain_hostname_and_domainname` because we're already writing the
variables to `/etc/dms-settings`. I left instructions in the script in
the form of TODO comments.

Because we now log the date for all messages of the changedetector, we
need to `tail` a bit more log than before.

target/scripts/check-for-changes.sh

@@ -5,48 +5,46 @@
 
 # shellcheck source=./helpers/index.sh
 source /usr/local/bin/helpers/index.sh
+# This script requires some environment variables to be properly set. This
+# includes POSTMASTER_ADDRESS (for alias (re-)generation), HOSTNAME and
+# DOMAINNAME (in ssl.sh).
+# shellcheck source=/dev/null
+source /etc/dms-settings
 
-function _log_date
-{
-  date +"%Y-%m-%d %H:%M:%S"
-}
+_log_with_date 'debug' 'Starting changedetector'
 
-LOG_DATE=$(_log_date)
-_notify 'task' "${LOG_DATE} Start check-for-changes script."
+# TODO in the future, when we do not use HOSTNAME but DMS_HOSTNAME everywhere,
+# TODO we can delete this call as we needn't calculate the names twice
+# ATTENTION: Do not remove!
+#            This script requies HOSTNAME and DOMAINNAME
+#            to be properly set.
+_obtain_hostname_and_domainname
 
-# ? --------------------------------------------- Checks
-
-cd /tmp/docker-mailserver || exit 1
+if ! cd /tmp/docker-mailserver &>/dev/null
+then
+  _exit_with_error "Could not change into '/tmp/docker-mailserver/' directory"
+fi
 
 # check postfix-accounts.cf exist else break
 if [[ ! -f postfix-accounts.cf ]]
 then
-  _notify 'inf' "${LOG_DATE} postfix-accounts.cf is missing! This should not run! Exit!"
-  exit 0
+  _exit_with_error "'/tmp/docker-mailserver/postfix-accounts.cf' is missing"
 fi
 
 # verify checksum file exists; must be prepared by start-mailserver.sh
 if [[ ! -f ${CHKSUM_FILE} ]]
 then
-  _notify 'err' "${LOG_DATE} ${CHKSUM_FILE} is missing! Start script failed? Exit!"
-  exit 0
+  _exit_with_error "'/tmp/docker-mailserver/${CHKSUM_FILE}' is missing"
 fi
 
-# ? --------------------------------------------- Actual script begins
-
-# determine postmaster address, duplicated from start-mailserver.sh
-# this script previously didn't work when POSTMASTER_ADDRESS was empty
-_obtain_hostname_and_domainname
-
-PM_ADDRESS="${POSTMASTER_ADDRESS:=postmaster@${DOMAINNAME}}"
-_notify 'inf' "${LOG_DATE} Using postmaster address ${PM_ADDRESS}"
-
 REGEX_NEVER_MATCH="(?\!)"
 
+_log_with_date 'trace' "Using postmaster address '${POSTMASTER_ADDRESS}'"
+
 # Change detection delayed during startup to avoid conflicting writes
 sleep 10
 
-_notify 'inf' "$(_log_date) check-for-changes is ready"
+_log_with_date 'debug' "Chagedetector is ready"
 
 while true
 do
@@ -60,7 +58,7 @@ do
   # 2 – inaccessible or missing argument
   if [[ ${?} -eq 1 ]]
   then
-    _notify 'inf' "$(_log_date) Change detected"
+    _log_with_date 'info' 'Change detected'
     _create_lock # Shared config safety lock
     CHANGED=$(grep -Fxvf "${CHKSUM_FILE}" "${CHKSUM_FILE}.new" | sed 's/^[^ ]\+  //')
 
@@ -76,7 +74,7 @@ do
       || [[ ${CHANGED} =~ ${SSL_ALT_CERT_PATH:-${REGEX_NEVER_MATCH}} ]] \
       || [[ ${CHANGED} =~ ${SSL_ALT_KEY_PATH:-${REGEX_NEVER_MATCH}} ]]
       then
-        _notify 'inf' "Manual certificates have changed, extracting certs.."
+        _log_with_date 'debug' 'Manual certificates have changed - extracting certificates'
         # we need to run the SSL setup again, because the
         # certificates DMS is working with are copies of
         # the (now changed) files
@@ -87,7 +85,7 @@ do
     # extracted for `docker-mailserver` services to adjust to.
     elif [[ ${CHANGED} =~ /etc/letsencrypt/acme.json ]]
     then
-      _notify 'inf' "'/etc/letsencrypt/acme.json' has changed, extracting certs.."
+      _log_with_date 'debug' "'/etc/letsencrypt/acme.json' has changed - extracting certificates"
 
       # This breaks early as we only need the first successful extraction.
       # For more details see the `SSL_TYPE=letsencrypt` case handling in `setup-stack.sh`.
@@ -97,7 +95,7 @@ do
       FQDN_LIST=("${SSL_DOMAIN}" "${HOSTNAME}" "${DOMAINNAME}")
       for CERT_DOMAIN in "${FQDN_LIST[@]}"
       do
-        _notify 'inf' "Attempting to extract for '${CERT_DOMAIN}'"
+        _log_with_date 'trace' "Attempting to extract for '${CERT_DOMAIN}'"
 
         if _extract_certs_from_acme "${CERT_DOMAIN}"
         then
@@ -135,7 +133,7 @@ do
       chown -R 5000:5000 /var/mail
     fi
 
-    _notify 'inf' "Restarting services due to detected changes.."
+    _log_with_date 'debug' 'Restarting services due to detected changes'
 
     supervisorctl restart postfix
 
@@ -143,7 +141,7 @@ do
     [[ ${SMTP_ONLY} -ne 1 ]] && supervisorctl restart dovecot
 
     _remove_lock
-    _notify 'inf' "$(_log_date) Completed handling of detected change"
+    _log_with_date 'debug' 'Completed handling of detected change'
   fi
 
   # mark changes as applied

target/scripts/helpers/log.sh

@@ -92,30 +92,3 @@ function _log
 }
 
 function _log_with_date { _log "${1}" "$(date '+%Y-%m-%d %H:%M:%S')  ${2}" ; }
-
-# Still used by `check-for-changes.sh` for legacy / test purposes. Adjusting
-# `check-for-changes.sh` must be done with great care and requires some effort.
-# As a consequence, this function is kept to keep some of the original log for
-# `check-for-changes.sh` for tests to pass.
-function _notify
-{
-  { [[ -z ${1:-} ]] || [[ -z ${2:-} ]] ; } && return 0
-
-  local RESET LGREEN LYELLOW LRED RED LBLUE LGREY LMAGENTA
-
-  RESET='\e[0m' ; LGREEN='\e[92m' ; LYELLOW='\e[93m'
-  LRED='\e[31m' ; RED='\e[91m' ; LBLUE='\e[34m'
-  LGREY='\e[37m' ; LMAGENTA='\e[95m'
-
-  case "${1}" in
-    'tasklog'  ) echo "-e${3:-}" "[ ${LGREEN}TASKLOG${RESET} ]  ${2}"  ;;
-    'warn'     ) echo "-e${3:-}" "[ ${LYELLOW}WARNING${RESET} ]  ${2}" ;;
-    'err'      ) echo "-e${3:-}" "[  ${LRED}ERROR${RESET}  ]  ${2}"    ;;
-    'fatal'    ) echo "-e${3:-}" "[  ${RED}FATAL${RESET}  ]  ${2}"     ;;
-    'inf'      ) [[ ${DMS_DEBUG} -eq 1 ]] && echo "-e${3:-}" "[[  ${LBLUE}INF${RESET}  ]]  ${2}" ;;
-    'task'     ) [[ ${DMS_DEBUG} -eq 1 ]] && echo "-e${3:-}" "[[ ${LGREY}TASKS${RESET} ]]  ${2}" ;;
-    *          ) echo "-e${3:-}" "[  ${LMAGENTA}UNKNOWN${RESET}  ]  ${2}" ;;
-  esac
-
-  return 0
-}

test/mail_ssl_letsencrypt.bats

@@ -110,7 +110,7 @@ function teardown() {
     local TEST_DOCKER_ARGS=(
       --volume "${TEST_TMP_CONFIG}/letsencrypt/acme.json:/etc/letsencrypt/acme.json:ro"
       --env DMS_DEBUG=1
-      --env LOG_LEVEL=trace
+      --env LOG_LEVEL='trace'
       --env PERMIT_DOCKER='container'
       --env SSL_DOMAIN='*.example.test'
       --env SSL_TYPE='letsencrypt'
@@ -120,7 +120,7 @@ function teardown() {
     wait_for_service "${TEST_NAME}" 'changedetector'
 
     # Wait until the changedetector service startup delay is over:
-    repeat_until_success_or_timeout 20 sh -c "$(_get_service_logs 'changedetector') | grep 'check-for-changes is ready'"
+    repeat_until_success_or_timeout 20 sh -c "$(_get_service_logs 'changedetector') | grep 'Chagedetector is ready'"
   }
 
   # Test `acme.json` extraction works at container startup:
@@ -242,7 +242,7 @@ function _should_extract_on_changes() {
   # Expected log lines from the changedetector service:
   run $(_get_service_logs 'changedetector')
   assert_output --partial 'Change detected'
-  assert_output --partial "'/etc/letsencrypt/acme.json' has changed, extracting certs"
+  assert_output --partial "'/etc/letsencrypt/acme.json' has changed - extracting certificates"
   assert_output --partial "_extract_certs_from_acme | Certificate successfully extracted for '${EXPECTED_DOMAIN}'"
   assert_output --partial 'Restarting services due to detected changes'
   assert_output --partial 'postfix: stopped'
@@ -256,7 +256,7 @@ function _should_have_service_restart_count() {
   local NUM_RESTARTS=${1}
 
   # Count how many times postfix was restarted by the `changedetector` service:
-  run docker exec "${TEST_NAME}" sh -c "supervisorctl tail changedetector | grep -c 'postfix: started'"
+  run docker exec "${TEST_NAME}" sh -c "grep -c 'postfix: started' /var/log/supervisor/changedetector.log"
   assert_output "${NUM_RESTARTS}"
 }
 
@@ -302,7 +302,7 @@ function _should_be_equal_in_content() {
 function _get_service_logs() {
   local SERVICE=${1:-'mailserver'}
 
-  local CMD_LOGS=(docker exec "${TEST_NAME}" "supervisorctl tail ${SERVICE}")
+  local CMD_LOGS=(docker exec "${TEST_NAME}" "supervisorctl tail -2000 ${SERVICE}")
 
   # As the `mailserver` service logs are not stored in a file but output to stdout/stderr,
   # The `supervisorctl tail` command won't work; we must instead query via `docker logs`:

test/mail_ssl_manual.bats

@@ -22,6 +22,7 @@ function setup_file() {
         --volume "${PRIVATE_CONFIG}/:/tmp/docker-mailserver/" \
         --volume "$(pwd)/test/test-files/ssl/${DOMAIN_SSL_MANUAL}/with_ca/ecdsa/:/config/ssl/:ro" \
         --env DMS_DEBUG=1 \
+        --env LOG_LEVEL='trace' \
         --env SSL_TYPE='manual' \
         --env TLS_LEVEL='modern' \
         --env SSL_KEY_PATH="${SSL_KEY_PATH}" \