Improve logging significantly – color is back! (#1758)

* improve logging significantly
* now defaulting to warn
* final adjustments
* correcting not-escaped $ in sed

ENVIRONMENT.md

@@ -15,6 +15,18 @@
 - **0** => Debug disabled
 - 1 => Enables debug on startup
 
+##### SUPERVISOR_LOGLEVEL
+
+Here you can adjust the [log-level for Supervisor](http://supervisord.org/logging.html#activity-log-levels). Possible values are
+
+- critical => Only show critical messages
+- error => Only show erroneous output
+- **warn** => Show warnings
+- info => Normal informational output
+- debug => Also show debug messages
+
+The log-level will show everything in its class and above.
+
 ##### ENABLE_CLAMAV
 
 - **0** => Clamav is disabled

target/scripts/helper-functions.sh

@@ -97,7 +97,7 @@ for key, value in acme.items():
 
     echo "${KEY}" | base64 -d >/etc/letsencrypt/live/"${HOSTNAME}"/key.pem || exit 1
     echo "${CERT}" | base64 -d >/etc/letsencrypt/live/"${HOSTNAME}"/fullchain.pem || exit 1
-    echo "Cert found in /etc/letsencrypt/acme.json for ${1}"
+    _notify 'inf' "Cert found in /etc/letsencrypt/acme.json for ${1}"
 
     return 0
   else
@@ -110,22 +110,17 @@ export -f _extract_certs_from_acme
 
 function _notify
 {
-  local FINAL_MSG=''
-  local MSG="${2:-}"
-  local TYPE="${1:-}"
+  { [[ -z ${1:-} ]] || [[ -z ${2:-} ]] ; } && return
 
-  case "${TYPE}" in
-    'none'    ) FINAL_MSG=' ' ;;
-    'tasklog' ) FINAL_MSG="[ \e[0;92mTASKLOG\e[0m ]  ${MSG}" ;; # light green
-    'warn'    ) FINAL_MSG="[ \e[0;93mWARNING\e[0m ]  ${MSG}" ;; # light yellow
-    'err'     ) FINAL_MSG="[  \e[0;31mERROR\e[0m  ]  ${MSG}" ;; # light red
-    'fatal'   ) FINAL_MSG="[  \e[0;91mFATAL\e[0m  ]  ${MSG}" ;; # red
-    'inf'     ) [[ ${DMS_DEBUG} -eq 1 ]] && FINAL_MSG="[[ \e[0;34mINFO\e[0m ]]   ${MSG}" ;; # light blue
-    'task'    ) [[ ${DMS_DEBUG} -eq 1 ]] && FINAL_MSG="[[ \e[0;37mTASK\e[0m ]]   ${MSG}" ;; # light grey
+  case ${1} in
+    tasklog  ) echo "-e${3:-}" "[ \e[0;92mTASKLOG\e[0m ]  ${2}" ;; # light green
+    warn     ) echo "-e${3:-}" "[ \e[0;93mWARNING\e[0m ]  ${2}" ;; # light yellow
+    err      ) echo "-e${3:-}" "[  \e[0;31mERROR\e[0m  ]  ${2}" ;; # light red
+    fatal    ) echo "-e${3:-}" "[  \e[0;91mFATAL\e[0m  ]  ${2}" ;; # red
+    inf      ) [[ ${DMS_DEBUG} -eq 1 ]] && echo "-e${3:-}" "[[  \e[0;34mINF\e[0m  ]]  ${2}" ;; # light blue
+    task     ) [[ ${DMS_DEBUG} -eq 1 ]] && echo "-e${3:-}" "[[ \e[0;37mTASKS\e[0m ]]  ${2}" ;; # light grey
     *        ) ;;
   esac
-
-  [[ -n ${FINAL_MSG} ]] && echo "-e${3:-}" "${FINAL_MSG}"
 }
 export -f _notify
 

target/scripts/start-mailserver.sh

@@ -41,6 +41,7 @@ SPAMASSASSIN_SPAM_TO_INBOX="${SPAMASSASSIN_SPAM_TO_INBOX:=0}"
 SPOOF_PROTECTION="${SPOOF_PROTECTION:=0}"
 SRS_SENDER_CLASSES="${SRS_SENDER_CLASSES:=envelope_sender}"
 SSL_TYPE="${SSL_TYPE:=''}"
+SUPERVISOR_LOGLEVEL="${SUPERVISOR_LOGLEVEL:=warn}"
 TLS_LEVEL="${TLS_LEVEL:=modern}"
 VIRUSMAILS_DELETE_DELAY="${VIRUSMAILS_DELETE_DELAY:=7}"
 
@@ -90,6 +91,7 @@ function register_functions
 
   ################### >> setup funcs
 
+  _register_setup_function "_setup_supervisor"
   _register_setup_function "_setup_default_vars"
   _register_setup_function "_setup_file_permissions"
 
@@ -352,6 +354,26 @@ function setup
   done
 }
 
+function _setup_supervisor
+{
+  case ${SUPERVISOR_LOGLEVEL} in
+    critical | error | warn | info | debug )
+      sed -i -E \
+        "s+loglevel.*+loglevel = ${SUPERVISOR_LOGLEVEL}+g" \
+        /etc/supervisor/supervisord.conf
+      ;;
+    * )
+      _notify 'warn' \
+        "SUPERVISOR_LOGLEVEL value '${SUPERVISOR_LOGLEVEL}' unknown. Defaulting to 'warn'"
+      sed -i -E \
+        "s+loglevel.*+loglevel = warn+g" \
+        /etc/supervisor/supervisord.conf
+      ;;
+  esac
+
+  supervisorctl update
+}
+
 function _setup_default_vars
 {
   _notify 'task' "Setting up default variables"
@@ -368,9 +390,9 @@ function _setup_default_vars
   # ! needs to be a string comparison
   if [[ ${REPORT_RECIPIENT} == "0" ]]
   then
-    PFLOGSUMM_TRIGGER="${PFLOGSUMM_TRIGGER:="none"}"
+    PFLOGSUMM_TRIGGER="${PFLOGSUMM_TRIGGER:=none}"
   else
-    PFLOGSUMM_TRIGGER="${PFLOGSUMM_TRIGGER:="logrotate"}"
+    PFLOGSUMM_TRIGGER="${PFLOGSUMM_TRIGGER:=logrotate}"
   fi
 
   # expand address to simplify the rest of the script
@@ -420,6 +442,7 @@ function _setup_default_vars
     echo "SPOOF_PROTECTION=${SPOOF_PROTECTION}"
     echo "SRS_SENDER_CLASSES=${SRS_SENDER_CLASSES}"
     echo "SSL_TYPE=${SSL_TYPE}"
+    echo "SUPERVISOR_LOGLEVEL=${SUPERVISOR_LOGLEVEL}"
     echo "TLS_LEVEL=${TLS_LEVEL}"
     echo "VIRUSMAILS_DELETE_DELAY=${VIRUSMAILS_DELETE_DELAY}"
     echo "DMS_DEBUG=${DMS_DEBUG}"
@@ -808,7 +831,7 @@ function _setup_ldap
   fi
 
   # shellcheck disable=SC2016
-  sed -i -E 's+mydestination = $myhostname, +mydestination = +' /etc/postfix/main.cf
+  sed -i 's+mydestination = \$myhostname, +mydestination = +' /etc/postfix/main.cf
 
   return 0
 }
@@ -1918,7 +1941,7 @@ function _fix_cleanup_spamassassin
 
 function misc
 {
-  _notify 'tasklog' 'Startin misc'
+  _notify 'inf' 'Startin misc'
 
   for FUNC in "${FUNCS_MISC[@]}"
   do
@@ -2169,28 +2192,20 @@ function _start_changedetector
 
 if [[ ${DMS_DEBUG:-0} -eq 1 ]]
 then
-  _notify 'none'
-  _notify 'tasklog' 'ENVIRONMENT'
-  _notify 'none'
-
+  _notify 'inf' 'ENVIRONMENT'
   printenv
 fi
 
-_notify 'none'
-_notify 'tasklog' 'Welcome to docker-mailserver!'
-_notify 'none'
+_notify 'inf' 'Welcome to docker-mailserver!'
 
 register_functions
-
 check
 setup
 fix
 misc
 start_daemons
 
-_notify 'none'
 _notify 'tasklog' "${HOSTNAME} is up and running"
-_notify 'none'
 
 touch /var/log/mail/mail.log
 tail -fn 0 /var/log/mail/mail.log

target/supervisor/conf.d/supervisor-app.conf

@@ -4,10 +4,6 @@
 # Programs can be controlled like this: 'supervisorctl start fail2ban' 'supervisorctl stop fail2ban'
 # supervisor writes program statuses in /var/log/supervisor
 
-[supervisord]
-nodaemon=true
-strip_ansi=true
-
 [program:mailserver]
 startsecs=0
 autostart=true

target/supervisor/supervisord.conf

@@ -1,28 +1,31 @@
-; supervisor config file
-
 [unix_http_server]
-file=/dev/shm/supervisor.sock    ; (the path to the socket file)
-chmod=0700                       ; sockef file mode (default 0700)
+file = /dev/shm/supervisor.sock
+chmod = 0700
+chown = nobody:nogroup
+username = docker-mailserver
+password = docker-mailserver-password
 
 [supervisord]
-logfile=/var/log/supervisor/supervisord.log ; (main log file;default $CWD/supervisord.log)
-pidfile=/var/run/supervisord.pid ; (supervisord pidfile;default supervisord.pid)
-childlogdir=/var/log/supervisor            ; ('AUTO' child log dir, default $TEMP)
+user = root
+loglevel = warn
+nodaemon = true
+strip_ansi = false
+logfile = /var/log/supervisor/supervisord.log      ; default $CWD/supervisord.log
+pidfile = /var/run/supervisord.pid                 ; default supervisord.pid
+childlogdir = /var/log/supervisor                  ; default $TEMP ('AUTO' child log dir)
 
-; the below section must remain in the config file for RPC
-; (supervisorctl/web interface) to work, additional interfaces may be
-; added by defining them in separate rpcinterface: sections
+[supervisorctl]
+serverurl = unix:///dev/shm/supervisor.sock        ; use a 'unix://' path for a unix socket
+username = docker-mailserver
+password = docker-mailserver-password
+
+; must remain in config file for RPC (supervisorctl/web interface) to work, additional
+; interfaces may be added by defining them in separate rpcinterface: sections
 [rpcinterface:supervisor]
 supervisor.rpcinterface_factory = supervisor.rpcinterface:make_main_rpcinterface
 
-[supervisorctl]
-serverurl=unix:///dev/shm/supervisor.sock ; use a unix:// URL  for a unix socket
-
-; The [include] section can just contain the "files" setting.  This
-; setting can list multiple files (separated by whitespace or
-; newlines).  It can also contain wildcards.  The filenames are
-; interpreted as relative to this file.  Included files *cannot*
-; include files themselves.
-
+; The [include] section can just contain the "files" setting.  This setting can list multiple
+; files (separated by whitespace or newlines).  It can also contain wildcards.  The filenames
+; are interpreted as relative to this file.  Included files *cannot* include files themselves.
 [include]
 files = /etc/supervisor/conf.d/*.conf

test/mail_ssl_letsencrypt.bats

@@ -119,7 +119,6 @@ function teardown_file() {
   cp "$(private_config_path mail_lets_acme_json)/letsencrypt/acme-changed.json" "$(private_config_path mail_lets_acme_json)/acme.json"
   sleep 11
   run docker exec mail_lets_acme_json /bin/bash -c "supervisorctl tail changedetector"
-  assert_output --partial "Cert found in /etc/letsencrypt/acme.json for *.example.com"
   assert_output --partial "postfix: stopped"
   assert_output --partial "postfix: started"
   assert_output --partial "Change detected"