Merge pull request #810 from usrpro/feat-logging

Implement some degree of logging

CHANGELOG.md

@@ -77,6 +77,7 @@ v1.6.0 - unreleased
 - Enhancement: Added regex validation for alias username ([#764](https://github.com/Mailu/Mailu/issues/764))
 - Enhancement: Update documentation
 - Enhancement: Include favicon package ([#801](https://github.com/Mailu/Mailu/issues/801), ([#802](https://github.com/Mailu/Mailu/issues/802))
+- Enhancement: Add logging at critical places in python start.py scripts. Implement LOG_LEVEL to control verbosity ([#588](https://github.com/Mailu/Mailu/issues/588))
 - Upstream: Update Roundcube
 - Upstream: Update Rainloop
 - Bug: Rainloop fails with "domain not allowed" ([#93](https://github.com/Mailu/Mailu/issues/93))

core/dovecot/start.py

@@ -6,23 +6,40 @@ import socket
 import glob
 import multiprocessing
 import tenacity
+import logging as log
+import sys
 
 from tenacity import retry
 from podop import run_server
 
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
 
 def start_podop():
     os.setuid(8)
-    run_server(3 if "DEBUG" in os.environ else 0, "dovecot", "/tmp/podop.socket", [
+    run_server(0, "dovecot", "/tmp/podop.socket", [
 		("quota", "url", "http://admin/internal/dovecot/§"),
 		("auth", "url", "http://admin/internal/dovecot/§"),
 		("sieve", "url", "http://admin/internal/dovecot/§"),
     ])
 
-convert = lambda src, dst: open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+def convert(src, dst):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+
+@retry(
+    stop=tenacity.stop_after_attempt(100),
+    wait=tenacity.wait_random(min=2, max=5),
+    before=tenacity.before_log(log.getLogger("tenacity.retry"), log.DEBUG),
+    before_sleep=tenacity.before_sleep_log(log.getLogger("tenacity.retry"), log.INFO),
+    after=tenacity.after_log(log.getLogger("tenacity.retry"), log.DEBUG)
+    )
+def resolve(hostname):
+    logger = log.getLogger("resolve()")
+    logger.info(hostname)
+    return socket.gethostbyname(hostname)
 
 # Actual startup script
-resolve = retry(socket.gethostbyname, stop=tenacity.stop_after_attempt(100), wait=tenacity.wait_random(min=2, max=5))
 os.environ["FRONT_ADDRESS"] = resolve(os.environ.get("FRONT_ADDRESS", "front"))
 os.environ["REDIS_ADDRESS"] = resolve(os.environ.get("REDIS_ADDRESS", "redis"))
 if os.environ["WEBMAIL"] != "none":

core/nginx/config.py

@@ -2,11 +2,18 @@
 
 import jinja2
 import os
-
+import logging as log
-convert = lambda src, dst, args: open(dst, "w").write(jinja2.Template(open(src).read()).render(**args))
+import sys
 
 args = os.environ.copy()
 
+log.basicConfig(stream=sys.stderr, level=args.get("LOG_LEVEL", "WARNING"))
+
+def convert(src, dst, args):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**args))
+
 # Get the first DNS server
 with open("/etc/resolv.conf") as handle:
     content = handle.read().split()

core/postfix/start.py

@@ -7,14 +7,18 @@ import glob
 import shutil
 import tenacity
 import multiprocessing
+import logging as log
+import sys
 
 from tenacity import retry
 from podop import run_server
 
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
 
 def start_podop():
     os.setuid(100)
-    run_server(3 if "DEBUG" in os.environ else 0, "postfix", "/tmp/podop.socket", [
+    # TODO: Remove verbosity setting from Podop?
+    run_server(0, "postfix", "/tmp/podop.socket", [
 		("transport", "url", "http://admin/internal/postfix/transport/§"),
 		("alias", "url", "http://admin/internal/postfix/alias/§"),
 		("domain", "url", "http://admin/internal/postfix/domain/§"),
@@ -23,11 +27,24 @@ def start_podop():
         ("senderlogin", "url", "http://admin/internal/postfix/sender/login/§")
     ])
 
-convert = lambda src, dst: open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+def convert(src, dst):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+
+@retry(
+    stop=tenacity.stop_after_attempt(100),
+    wait=tenacity.wait_random(min=2, max=5),
+    before=tenacity.before_log(log.getLogger("tenacity.retry"), log.DEBUG),
+    before_sleep=tenacity.before_sleep_log(log.getLogger("tenacity.retry"), log.INFO),
+    after=tenacity.after_log(log.getLogger("tenacity.retry"), log.DEBUG)
+    )
+def resolve(hostname):
+    logger = log.getLogger("resolve()")
+    logger.info(hostname)
+    return socket.gethostbyname(hostname)
 
 # Actual startup script
-resolve = retry(socket.gethostbyname, stop=tenacity.stop_after_attempt(100), wait=tenacity.wait_random(min=2, max=5))
-
 os.environ["FRONT_ADDRESS"] = resolve(os.environ.get("FRONT_ADDRESS", "front"))
 os.environ["HOST_ANTISPAM"] = os.environ.get("HOST_ANTISPAM", "antispam:11332")
 os.environ["HOST_LMTP"] = os.environ.get("HOST_LMTP", "imap:2525")

docs/compose/.env

@@ -151,3 +151,6 @@ REAL_IP_FROM=
 
 # choose wether mailu bounces (no) or rejects (yes) mail when recipient is unknown (value: yes, no)
 REJECT_UNLISTED_RECIPIENT=
+
+# Log level threshold in start.py (value: CRITICAL, ERROR, WARNING, INFO, DEBUG, NOTSET)
+LOG_LEVEL=WARNING

docs/configuration.rst

@@ -91,6 +91,13 @@ The ``PASSWORD_SCHEME`` is the password encryption scheme. You should use the
 default value, unless you are importing password from a separate system and
 want to keep using the old password encryption scheme.
 
+The ``LOG_LEVEL`` setting is used by the python start-up scripts as a logging threshold.
+Log messages equal or higher than this priority will be printed.
+Can be one of: CRITICAL, ERROR, WARNING, INFO, DEBUG or NOTSET.
+See the `python docs`_ for more information.
+
+.. _`python docs`: https://docs.python.org/3.6/library/logging.html#logging-levels
+
 Infrastructure settings
 -----------------------
 

optional/clamav/start.py

@@ -1,12 +1,21 @@
 #!/usr/bin/python3
 
 import os
+import logging as log
+import sys
+
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
+logger=log.getLogger(__name__)
 
 # Bootstrap the database if clamav is running for the first time
-os.system("[ -f /data/main.cvd ] || freshclam")
+if not os.path.isfile("/data/main.cvd"):
+    logger.info("Starting primary virus DB download")
+    os.system("freshclam")
 
 # Run the update daemon
+logger.info("Starting the update daemon")
 os.system("freshclam -d -c 6")
 
 # Run clamav
+logger.info("Starting clamav")
 os.system("clamd")

services/rspamd/start.py

@@ -5,13 +5,31 @@ import os
 import socket
 import glob
 import tenacity
+import logging as log
+import sys
+
 from tenacity import retry
 
-convert = lambda src, dst: open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
+
+def convert(src, dst):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+
+@retry(
+    stop=tenacity.stop_after_attempt(100),
+    wait=tenacity.wait_random(min=2, max=5),
+    before=tenacity.before_log(log.getLogger("tenacity.retry"), log.DEBUG),
+    before_sleep=tenacity.before_sleep_log(log.getLogger("tenacity.retry"), log.INFO),
+    after=tenacity.after_log(log.getLogger("tenacity.retry"), log.DEBUG)
+    )
+def resolve(hostname):
+    logger = log.getLogger("resolve()")
+    logger.info(hostname)
+    return socket.gethostbyname(hostname)
 
 # Actual startup script
-resolve = retry(socket.gethostbyname, stop=tenacity.stop_after_attempt(100), wait=tenacity.wait_random(min=2, max=5))
-
 os.environ["FRONT_ADDRESS"] = resolve(os.environ.get("FRONT_ADDRESS", "front"))
 
 if "HOST_REDIS" not in os.environ: os.environ["HOST_REDIS"] = "redis"

services/unbound/start.py

@@ -2,8 +2,16 @@
 
 import jinja2
 import os
+import logging as log
+import sys
+
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
+
+def convert(src, dst):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
 
-convert = lambda src, dst: open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
 convert("/unbound.conf", "/etc/unbound/unbound.conf")
 
 os.execv("/usr/sbin/unbound", ["-c /etc/unbound/unbound.conf"])

setup/flavors/compose/mailu.env

@@ -160,3 +160,6 @@ REAL_IP_FROM={{ real_ip_from }}
 
 # choose wether mailu bounces (no) or rejects (yes) mail when recipient is unknown (value: yes, no)
 REJECT_UNLISTED_RECIPIENT={{ reject_unlisted_recipient }}
+
+# Log level threshold in start.py (value: CRITICAL, ERROR, WARNING, INFO, DEBUG, NOTSET)
+LOG_LEVEL=WARNING

webmails/rainloop/start.py

@@ -3,8 +3,15 @@
 import jinja2
 import os
 import shutil
+import logging as log
+import sys
 
-convert = lambda src, dst: open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
+
+def convert(src, dst):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
 
 # Actual startup script
 os.environ["FRONT_ADDRESS"] = os.environ.get("FRONT_ADDRESS", "front")

webmails/roundcube/start.py

@@ -2,8 +2,15 @@
 
 import os
 import jinja2
+import logging as log
+import sys
 
-convert = lambda src, dst: open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
+log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", "WARNING"))
+
+def convert(src, dst):
+    logger = log.getLogger("convert()")
+    logger.debug("Source: %s, Destination: %s", src, dst)
+    open(dst, "w").write(jinja2.Template(open(src).read()).render(**os.environ))
 
 os.environ["MAX_FILESIZE"] = str(int(int(os.environ.get("MESSAGE_SIZE_LIMIT"))*0.66/1048576))