scripts: update log format (#4035)

Co-authored-by: Brennan Kinney <5098581+polarathene@users.noreply.github.com>
2024-05-29 02:28:51 +02:00 · 2024-05-29 02:28:51 +02:00 · f8b3f40276
parent 95d965fb76
commit f8b3f40276
6 changed files with 40 additions and 36 deletions
--- 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 `<RFC 3339 TIMESTAMP> <LOG LEVEL> <LOG EVENT SRC>: <MESSAGE>` ([#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.
--- 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
 }
--- 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,
--- 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
--- 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
 }

--- 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: