From f8b3f402763a8ac1112971ec53a2041398e7ce4c Mon Sep 17 00:00:00 2001 From: Georg Lauterbach <44545919+georglauterbach@users.noreply.github.com> Date: Wed, 29 May 2024 02:28:51 +0200 Subject: [PATCH] scripts: update log format (#4035) Co-authored-by: Brennan Kinney <5098581+polarathene@users.noreply.github.com> --- CHANGELOG.md | 2 ++ target/scripts/check-for-changes.sh | 30 +++++++++---------- target/scripts/helpers/log.sh | 28 +++++++++-------- target/scripts/update-check.sh | 12 ++++---- .../set1/spam_virus/rspamd_partly.bats | 2 +- test/tests/parallel/set1/tls/dhparams.bats | 2 +- 6 files changed, 40 insertions(+), 36 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e2285f6d..30511983 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -43,6 +43,8 @@ The most noteworthy change of this release is the update of the container's base - **Removed support for Solr integration:** ([#4025](https://github.com/docker-mailserver/docker-mailserver/pull/4025)) - This was a community contributed feature for FTS (Full Text Search), the docs advise using an image that has not been maintained for over 2 years and lacks ARM64 support. Based on user engagement over the years this feature has very niche value to continue to support, thus is being removed. - If you use Solr, support can be restored if you're willing to contribute docs for the feature that resolves the concerns raised +- **Log**: + - The format of DMS specific logs (_from our scripts, not running services_) has been changed. The new format is ` : ` ([#4035](https://github.com/docker-mailserver/docker-mailserver/pull/4035)) - **rsyslog:** - Debian 12 adjusted the `rsyslog` configuration for the default file template from `RSYSLOG_TraditionalFileFormat` to `RSYSLOG_FileFormat` (_upstream default since 2012_). This change may affect you if you have any monitoring / analysis of log output (_eg: `mail.log` / `docker logs`_). - The two formats are roughly equivalent to [RFC 3164](https://www.rfc-editor.org/rfc/rfc3164)) and [RFC 5424](https://datatracker.ietf.org/doc/html/rfc5424#section-1) respectively. diff --git a/target/scripts/check-for-changes.sh b/target/scripts/check-for-changes.sh index 3f268710..bf5cd90b 100755 --- a/target/scripts/check-for-changes.sh +++ b/target/scripts/check-for-changes.sh @@ -7,7 +7,7 @@ # shellcheck source=./helpers/index.sh source /usr/local/bin/helpers/index.sh -_log_with_date 'debug' 'Starting changedetector' +_log 'debug' 'Starting changedetector' # ATTENTION: Do not remove! # This script requires some environment variables to be properly set. @@ -30,9 +30,9 @@ if [[ ! -f ${CHKSUM_FILE} ]]; then _exit_with_error "'${CHKSUM_FILE}' is missing" 0 fi -_log_with_date 'trace' "Using postmaster address '${POSTMASTER_ADDRESS}'" +_log 'trace' "Using postmaster address '${POSTMASTER_ADDRESS}'" -_log_with_date 'debug' "Changedetector is ready" +_log 'debug' "Changedetector is ready" function _check_for_changes() { # get chksum and check it, no need to lock config yet @@ -44,7 +44,7 @@ function _check_for_changes() { # 1 – files differ # 2 – inaccessible or missing argument if [[ ${?} -eq 1 ]]; then - _log_with_date 'info' 'Change detected' + _log 'info' 'Change detected' _create_lock # Shared config safety lock local CHANGED @@ -52,7 +52,7 @@ function _check_for_changes() { _handle_changes _remove_lock - _log_with_date 'debug' 'Completed handling of detected change' + _log 'debug' 'Completed handling of detected change' # mark changes as applied mv "${CHKSUM_FILE}.new" "${CHKSUM_FILE}" @@ -64,7 +64,7 @@ function _handle_changes() { local VHOST_UPDATED=0 # These two configs are the source for /etc/postfix/vhost (managed mail domains) if [[ ${CHANGED} =~ ${DMS_DIR}/postfix-(accounts|virtual).cf ]]; then - _log_with_date 'trace' 'Regenerating vhosts (Postfix)' + _log 'trace' 'Regenerating vhosts (Postfix)' # Regenerate via `helpers/postfix.sh`: _create_postfix_vhost @@ -75,7 +75,7 @@ function _handle_changes() { _postfix_dovecot_changes _rspamd_changes - _log_with_date 'debug' 'Reloading services due to detected changes' + _log 'debug' 'Reloading services due to detected changes' [[ ${ENABLE_AMAVIS} -eq 1 ]] && _reload_amavis _reload_postfix @@ -119,7 +119,7 @@ function _postfix_dovecot_changes() { || [[ ${CHANGED} =~ ${DMS_DIR}/dovecot-quotas.cf ]] \ || [[ ${CHANGED} =~ ${DMS_DIR}/dovecot-masters.cf ]] then - _log_with_date 'trace' 'Regenerating accounts (Dovecot + Postfix)' + _log 'trace' 'Regenerating accounts (Dovecot + Postfix)' [[ ${SMTP_ONLY} -ne 1 ]] && _create_accounts fi @@ -131,7 +131,7 @@ function _postfix_dovecot_changes() { || [[ ${CHANGED} =~ ${DMS_DIR}/postfix-relaymap.cf ]] \ || [[ ${CHANGED} =~ ${DMS_DIR}/postfix-sasl-password.cf ]] then - _log_with_date 'trace' 'Regenerating relay config (Postfix)' + _log 'trace' 'Regenerating relay config (Postfix)' _process_relayhost_configs fi @@ -159,14 +159,14 @@ function _ssl_changes() { || [[ ${CHANGED} =~ ${SSL_ALT_CERT_PATH:-${REGEX_NEVER_MATCH}} ]] \ || [[ ${CHANGED} =~ ${SSL_ALT_KEY_PATH:-${REGEX_NEVER_MATCH}} ]] then - _log_with_date 'debug' 'Manual certificates have changed - extracting certificates' + _log 'debug' 'Manual certificates have changed - extracting certificates' _setup_ssl fi # `acme.json` is only relevant to Traefik, and is where it stores the certificates it manages. # When a change is detected it's assumed to be a possible cert renewal that needs to be # extracted for `docker-mailserver` services to adjust to. elif [[ ${CHANGED} =~ /etc/letsencrypt/acme.json ]]; then - _log_with_date 'debug' "'/etc/letsencrypt/acme.json' has changed - extracting certificates" + _log 'debug' "'/etc/letsencrypt/acme.json' has changed - extracting certificates" _setup_ssl # Prevent an unnecessary change detection from the newly extracted cert files by updating their hashes in advance: @@ -188,23 +188,23 @@ function _rspamd_changes() { # "${RSPAMD_DMS_D}/override.d" if [[ ${CHANGED} =~ ${RSPAMD_DMS_OVERRIDE_D}/.* ]]; then - _log_with_date 'trace' 'Rspamd - Copying configuration overrides' + _log 'trace' 'Rspamd - Copying configuration overrides' rm "${RSPAMD_OVERRIDE_D}"/* cp "${RSPAMD_DMS_OVERRIDE_D}"/* "${RSPAMD_OVERRIDE_D}" fi # "${RSPAMD_DMS_D}/custom-commands.conf" if [[ ${CHANGED} =~ ${RSPAMD_DMS_CUSTOM_COMMANDS_F} ]]; then - _log_with_date 'trace' 'Rspamd - Generating new configuration from custom commands' + _log 'trace' 'Rspamd - Generating new configuration from custom commands' _rspamd_handle_user_modules_adjustments fi # "${RSPAMD_DMS_D}/dkim" if [[ ${CHANGED} =~ ${RSPAMD_DMS_DKIM_D} ]]; then - _log_with_date 'trace' 'Rspamd - DKIM files updated' + _log 'trace' 'Rspamd - DKIM files updated' fi - _log_with_date 'debug' 'Rspamd configuration has changed - restarting service' + _log 'debug' 'Rspamd configuration has changed - restarting service' supervisorctl restart rspamd fi } diff --git a/target/scripts/helpers/log.sh b/target/scripts/helpers/log.sh index d771a3f5..d98f96a8 100644 --- a/target/scripts/helpers/log.sh +++ b/target/scripts/helpers/log.sh @@ -53,8 +53,7 @@ function _log() { return 1 fi - local LEVEL_AS_INT - local MESSAGE="${RESET}[" + local LEVEL_AS_INT LOG_COLOR LOG_LEVEL_NAME MESSAGE case "$(_get_log_level_or_default)" in ( 'trace' ) LEVEL_AS_INT=5 ;; @@ -67,27 +66,35 @@ function _log() { case "${1}" in ( 'trace' ) [[ ${LEVEL_AS_INT} -ge 5 ]] || return 0 - MESSAGE+=" ${CYAN}TRACE " + LOG_COLOR='CYAN' + LOG_LEVEL_NAME='TRACE' ;; ( 'debug' ) [[ ${LEVEL_AS_INT} -ge 4 ]] || return 0 - MESSAGE+=" ${PURPLE}DEBUG " + LOG_COLOR='PURPLE' + LOG_LEVEL_NAME='DEBUG' ;; ( 'info' ) [[ ${LEVEL_AS_INT} -ge 3 ]] || return 0 - MESSAGE+=" ${BLUE}INF " + LOG_COLOR='BLUE' + # the whitespace is intentional (for alignment purposes) + LOG_LEVEL_NAME='INFO ' ;; ( 'warn' ) [[ ${LEVEL_AS_INT} -ge 2 ]] || return 0 - MESSAGE+=" ${LYELLOW}WARNING " + LOG_COLOR='LYELLOW' + # the whitespace is intentional (for alignment purposes) + LOG_LEVEL_NAME='WARN ' ;; ( 'error' ) [[ ${LEVEL_AS_INT} -ge 1 ]] || return 0 - MESSAGE+=" ${LRED}ERROR " ;; + LOG_COLOR='LRED' + LOG_LEVEL_NAME='ERROR' + ;; ( * ) _log 'error' "Call to '_log' with invalid log level argument '${1}'" @@ -95,7 +102,7 @@ function _log() { ;; esac - MESSAGE+="${RESET}] ${2}" + MESSAGE="$(date --rfc-3339='seconds') ${!LOG_COLOR}${LOG_LEVEL_NAME}${RESET} $(basename "${0}"): ${2}" if [[ ${1} =~ ^(warn|error)$ ]]; then echo -e "${MESSAGE}" >&2 @@ -104,11 +111,6 @@ function _log() { fi } -# Like `_log` but adds a timestamp in front of the message. -function _log_with_date() { - _log "${1}" "$(date '+%Y-%m-%d %H:%M:%S') ${2}" -} - # Get the value of the environment variable LOG_LEVEL if # it is set. Otherwise, try to query the common environment # variables file. If this does not yield a value either, diff --git a/target/scripts/update-check.sh b/target/scripts/update-check.sh index 257fc37d..f00bfcb3 100755 --- a/target/scripts/update-check.sh +++ b/target/scripts/update-check.sh @@ -10,8 +10,8 @@ CHANGELOG_URL='https://github.com/docker-mailserver/docker-mailserver/blob/maste # check for correct syntax # number + suffix. suffix must be 's' for seconds, 'm' for minutes, 'h' for hours or 'd' for days. if [[ ! ${UPDATE_CHECK_INTERVAL} =~ ^[0-9]+[smhd]{1}$ ]]; then - _log_with_date 'warn' "Invalid 'UPDATE_CHECK_INTERVAL' value '${UPDATE_CHECK_INTERVAL}'" - _log_with_date 'warn' 'Falling back to daily update checks' + _log 'warn' "Invalid 'UPDATE_CHECK_INTERVAL' value '${UPDATE_CHECK_INTERVAL}'" + _log 'warn' 'Falling back to daily update checks' UPDATE_CHECK_INTERVAL='1d' fi @@ -22,7 +22,7 @@ while true; do # did we get a valid response? if [[ ${LATEST} =~ ^[0-9]+\.[0-9]+\.[0-9]+$ ]]; then - _log_with_date 'debug' 'Remote version information fetched' + _log 'debug' 'Remote version information fetched' # compare versions if dpkg --compare-versions "${VERSION}" lt "${LATEST}"; then @@ -38,15 +38,15 @@ Latest version: ${LATEST} Changelog: ${CHANGELOG_URL}#END EOF - _log_with_date 'info' "Update available [ ${VERSION} --> ${LATEST} ]" + _log 'info' "Update available [ ${VERSION} --> ${LATEST} ]" # only notify once echo "${MAIL}" | mail -s "Mailserver update available! [ ${VERSION} --> ${LATEST} ]" "${POSTMASTER_ADDRESS}" && exit 0 else - _log_with_date 'info' 'No update available' + _log 'info' 'No update available' fi else - _log_with_date 'warn' 'Update check failed' + _log 'warn' 'Update check failed' fi # check again in 'UPDATE_CHECK_INTERVAL' time diff --git a/test/tests/parallel/set1/spam_virus/rspamd_partly.bats b/test/tests/parallel/set1/spam_virus/rspamd_partly.bats index b647f562..a1afc9a3 100644 --- a/test/tests/parallel/set1/spam_virus/rspamd_partly.bats +++ b/test/tests/parallel/set1/spam_virus/rspamd_partly.bats @@ -44,7 +44,7 @@ function teardown_file() { _default_teardown ; } run docker logs "${CONTAINER_NAME}" assert_success for SERVICE in 'Amavis/SA' 'OpenDKIM' 'OpenDMARC' 'policyd-spf'; do - assert_output --regexp ".*WARNING.*Running ${SERVICE} & Rspamd at the same time is discouraged" + assert_output --regexp ".*WARN.*Running ${SERVICE} & Rspamd at the same time is discouraged" done } diff --git a/test/tests/parallel/set1/tls/dhparams.bats b/test/tests/parallel/set1/tls/dhparams.bats index 8b3047d1..86586f28 100644 --- a/test/tests/parallel/set1/tls/dhparams.bats +++ b/test/tests/parallel/set1/tls/dhparams.bats @@ -50,7 +50,7 @@ function teardown() { _default_teardown ; } # Should emit a warning: run docker logs "${CONTAINER_NAME}" assert_success - assert_output --partial '[ WARNING ] Using self-generated dhparams is considered insecure - unless you know what you are doing, please remove' + assert_output --partial 'Using self-generated dhparams is considered insecure - unless you know what you are doing, please remove' } # Ensures the docker image services (Postfix and Dovecot) have the expected DH files: