Merge #3008

3008: Fix issues with log filter and remove POSTFIX_LOG_FILE r=mergify[bot] a=Diman0

## What type of PR?

bug-fix

## What does this PR do?
Fixed log filter not filtering out log messages for dovecot/nginx/postfix.
Fixed postfix not logging to standard out.
Fixed not all containers logging to journald.
Removed POSTFIX_LOG_FILE functionality. A new FAQ entry is created that documents how to log to file with journald & rsyslog.

Thank you `@Lex999` for providing the sample code in #2839 for how to capture the standard out of called sub processes.

### Related issue(s)
- closes #2839
- closes #2819 
- closes #2939 

## Prerequisites
Before we can consider review and merge, please make sure the following list is done and checked.
If an entry in not applicable, you can check it or remove it from the list.

- [x] In case of feature or enhancement: documentation updated accordingly
- [x] Unless it's docs or a minor change: add [changelog](https://mailu.io/master/contributors/workflow.html#changelog) entry file.


Co-authored-by: Dimitri Huisman <diman@huisman.xyz>

core/base/libs/socrate/socrate/system.py

@@ -6,6 +6,8 @@ import re
 from pwd import getpwnam
 import socket
 import tenacity
+import subprocess
+import threading
 
 @tenacity.retry(stop=tenacity.stop_after_attempt(100),
                 wait=tenacity.wait_random(min=2, max=5))
@@ -27,7 +29,7 @@ def _coerce_value(value):
     return value
 
 class LogFilter(object):
-    def __init__(self, stream, re_patterns, log_file):
+    def __init__(self, stream, re_patterns):
         self.stream = stream
         if isinstance(re_patterns, list):
             self.pattern = re.compile('|'.join([f'(?:{pattern})' for pattern in re_patterns]))
@@ -36,7 +38,6 @@ class LogFilter(object):
         else:
             self.pattern = re_patterns
         self.found = False
-        self.log_file = log_file
 
     def __getattr__(self, attr_name):
         return getattr(self.stream, attr_name)
@@ -48,12 +49,6 @@ class LogFilter(object):
             if not self.pattern.search(data):
                 self.stream.write(data)
                 self.stream.flush()
-                if self.log_file:
-                    try:
-                        with open(self.log_file, 'a', encoding='utf-8') as l:
-                            l.write(data)
-                    except:
-                        pass
             else:
                 # caught bad pattern
                 self.found = True
@@ -74,10 +69,10 @@ def _is_compatible_with_hardened_malloc():
                 return False
     return True
 
-def set_env(required_secrets=[], log_filters=[], log_file=None):
+def set_env(required_secrets=[], log_filters=[]):
     if log_filters:
-        sys.stdout = LogFilter(sys.stdout, log_filters, log_file)
+        sys.stdout = LogFilter(sys.stdout, log_filters)
-        sys.stderr = LogFilter(sys.stderr, log_filters, log_file)
+        sys.stderr = LogFilter(sys.stderr, log_filters)
     log.basicConfig(stream=sys.stderr, level=os.environ.get("LOG_LEVEL", 'WARNING'))
 
     if not 'LD_PRELOAD' in os.environ and _is_compatible_with_hardened_malloc():
@@ -115,3 +110,24 @@ def drop_privs_to(username='mailu'):
     os.setgid(pwnam.pw_gid)
     os.setuid(pwnam.pw_uid)
     os.environ['HOME'] = pwnam.pw_dir
+
+# forwards text lines from src to dst in an infinite loop
+def forward_text_lines(src, dst):
+    while True:
+        current_line = src.readline()
+        dst.write(current_line)
+
+
+# runs a process and passes its standard/error output to the standard/error output of the current python script
+def run_process_and_forward_output(cmd):
+    process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True)
+
+    stdout_thread = threading.Thread(target=forward_text_lines, args=(process.stdout, sys.stdout))
+    stdout_thread.daemon = True
+    stdout_thread.start()
+
+    stderr_thread = threading.Thread(target=forward_text_lines, args=(process.stderr, sys.stderr))
+    stderr_thread.daemon = True
+    stderr_thread.start()
+
+    process.wait()

core/dovecot/start.py

@@ -3,13 +3,11 @@
 import os
 import glob
 import multiprocessing
-import logging as log
-import sys
 
 from podop import run_server
 from socrate import system, conf
 
-system.set_env(log_filters=r'Error\: SSL context initialization failed, disabling SSL\: Can\'t load SSL certificate \(ssl_cert setting\)\: The certificate is empty$')
+system.set_env(log_filters=[r'Error\: SSL context initialization failed, disabling SSL\: Can\'t load SSL certificate \(ssl_cert setting\)\: The certificate is empty$'])
 
 def start_podop():
     system.drop_privs_to('mail')
@@ -35,4 +33,5 @@ os.system("chown mail:mail /mail")
 os.system("chown -R mail:mail /var/lib/dovecot /conf")
 
 multiprocessing.Process(target=start_podop).start()
-os.system("dovecot -c /etc/dovecot/dovecot.conf -F")
+cmd = ['/usr/sbin/dovecot', '-c', '/etc/dovecot/dovecot.conf', '-F']
+system.run_process_and_forward_output(cmd)

core/nginx/start.py

@@ -4,7 +4,7 @@ import os
 import subprocess
 from socrate import system
 
-system.set_env(log_filters=r'could not be resolved \(\d\: [^\)]+\) while in resolving client address, client\: [^,]+, server: [^\:]+\:(25,110,143,587,465,993,995)$')
+system.set_env(log_filters=r'could not be resolved \(\d\: [^\)]+\) while in resolving client address, client\: [^,]+, server: [^\:]+\:(25|110|143|587|465|993|995)$')
 
 # Check if a stale pid file exists
 if os.path.exists("/var/run/nginx.pid"):
@@ -17,4 +17,5 @@ elif os.environ["TLS_FLAVOR"] in [ "mail", "cert" ]:
 
 subprocess.call(["/config.py"])
 os.system("dovecot -c /etc/dovecot/proxy.conf")
-os.execv("/usr/sbin/nginx", ["nginx", "-g", "daemon off;"])
+cmd = ['/usr/sbin/nginx', '-g', 'daemon off;']
+system.run_process_and_forward_output(cmd)

core/postfix/start.py

@@ -13,8 +13,8 @@ from socrate import system, conf
 system.set_env(log_filters=[
     r'(dis)?connect from localhost\[(\:\:1|127\.0\.0\.1)\]( quit=1 commands=1)?$',
     r'haproxy read\: short protocol header\: QUIT$',
-    r'discarding EHLO keywords\: PIPELINING$',
+    r'discarding EHLO keywords\: PIPELINING$'
-    ], log_file=os.environ.get('POSTFIX_LOG_FILE'))
+    ])
 
 os.system("flock -n /queue/pid/master.pid rm /queue/pid/master.pid")
 
@@ -100,4 +100,5 @@ os.system("/usr/libexec/postfix/post-install meta_directory=/etc/postfix create-
 # Before starting postfix, we need to check permissions on /queue
 # in the event that postfix,postdrop id have changed
 os.system("postfix set-permissions")
-os.system("postfix start-fg")
+cmd = ['postfix', 'start-fg']
+system.run_process_and_forward_output(cmd)

docs/configuration.rst

@@ -380,22 +380,6 @@ To disable all plugins just set ``ROUNDCUBE_PLUGINS`` to ``mailu``.
 
 To configure a plugin add php files named ``*.inc.php`` to roundcube's :ref:`override section <override-label>`.
 
-Mail log settings
------------------
-
-By default, all services log directly to stdout/stderr. Logs can be collected by any docker log processing solution.
-
-Postfix writes the logs to a syslog server which logs to stdout. This is used to filter
-out messages from the healthcheck. In some situations, a separate mail log is required
-(e.g. for legal reasons). The syslog server can be configured to write log files to a volume.
-It can be configured with the following option:
-
-- ``POSTFIX_LOG_FILE``: The file to log the mail log to. When enabled, the syslog server will also log to stdout.
-
-When ``POSTFIX_LOG_FILE`` is enabled, the logrotate program will automatically rotate the
-logs every week and keep 52 logs. To override the logrotate configuration, create the file logrotate.conf
-with the desired configuration in the :ref:`Postfix overrides folder<override-label>`.
-
 .. _header_authentication:
 
 Header authentication using an external proxy

docs/faq.rst

@@ -451,7 +451,7 @@ down and up again. A container restart is not sufficient.
 SMTP Banner from overrides/postfix.cf is ignored
 ````````````````````````````````````````````````
 
-Any mail related connection is proxied by nginx. Therefore the SMTP Banner is also set by nginx. Overwriting in overrides/postfix.cf does not apply.
+Any mail related connection is proxied by the front container. Therefore the SMTP Banner is also set by front container. Overwriting in overrides/postfix.cf does not apply.
 
 *Issue reference:* `1368`_.
 
@@ -922,3 +922,64 @@ I see a lot of "Unable to lookup the TLSA record for XXX. Is the DNSSEC zone oka
 There may be multiple causes for it but if you are running docker 24.0.0, odds are you are `experiencing this docker bug`_ and the workaround is to switch to a different version of docker.
 
 .. _`experiencing this docker bug`: https://github.com/Mailu/Mailu/issues/2827
+
+How can I view and export the logs of a Mailu container?
+````````````````````````````````````````````````````````
+
+In some situations, a separate log is required. For example a separate mail log (from postfix) could be required due to legal reasons.
+
+All Mailu containers log the output to journald. The logs are written to journald with the tag:
+
+| mailu-<service name>
+| where <service-name> is the name of the service in the docker-compose.yml file.
+| For example, the service running postfix is called smtp. To view the postfix logs use:
+
+.. code-block:: bash
+
+  journalctl -t mailu-smtp
+
+Note: ``SHIFT+G`` can be used to jump to the end of the log file. ``G`` can be used to jump back to the top of the log file.
+
+To export the log files from journald to the file system, the logs could be imported into a syslog program like ``rsyslog``.
+Via ``rsyslog`` the container specific logs could be written to a separate file using a filter.
+
+Below are the steps for writing the postfix (mail) logs to a log file on the file system.
+
+1. Install the ``rsyslog`` package. Note: on most distributions this program is already installed.
+2. Edit ``/etc/systemd/journald.conf``.
+3. Enable ``ForwardToSyslog=yes``. Note: on most distributions this is already enabled by default. This forwards journald to syslog.
+4. ``sudo touch /var/log/postfix.log``. This step creates the mail log file.
+5. ``sudo chown syslog:syslog /var/log/postfix.log``. This provides rsyslog the permissions for accessing this file.
+6. Create a new config file in ``/etc/rsyslog.d/export-postfix.conf``
+7. Add ``:programname, contains, "mailu-smtp" /var/log/postfix.log``. This instructs rsyslog to write the logs for mailu-smtp to a log file on file system.
+8. ``sudo systemctl restart systemd-journald.service``
+9. ``sudo systemctl restart rsyslog``
+10. All messages from the smtp/postfix container are now logged to ``/var/log/postfix.log``.
+11. Rsyslog does not perform log rotation. The program (package) ``log rotate`` can be used for this task. Install the ``logrotate`` package.
+12. Modify the existing configuration file for rsyslog: ``sudo nano /etc/logrotate.d/rsyslog``
+13. Add at the top add: ``/var/log/postfix.log``. Of course you can also use your own configuration. This is just an example. A complete example for configuring log rotate is:
+
+.. code-block:: bash
+
+  /var/log/postfix.log
+  {
+       rotate 4
+       weekly
+       missingok
+       notifempty
+       compress
+       delaycompress
+       sharedscripts
+       postrotate
+           /usr/lib/rsyslog/rsyslog-rotate
+       endscript
+  }
+
+.. code-block:: bash
+
+  #!/bin/sh
+  #/usr/lib/rsyslog/rsyslog-rotate
+
+  if [ -d /run/systemd/system ]; then
+      systemctl kill -s HUP rsyslog.service
+  fi

setup/flavors/compose/docker-compose.yml

@@ -58,6 +58,10 @@ services:
   resolver:
     image: ${DOCKER_ORG:-ghcr.io/mailu}/${DOCKER_PREFIX:-}unbound:${MAILU_VERSION:-{{ version }}}
     env_file: {{ env }}
+    logging:
+      driver: journald
+      options:
+        tag: mailu-resolver
     restart: always
     networks:
       default:
@@ -220,7 +224,7 @@ services:
     logging:
       driver: journald
       options:
-        tag: mailu-clamav
+        tag: mailu-antivirus
     networks:
       - clamav
     volumes:
@@ -237,6 +241,10 @@ services:
   webdav:
     image: ${DOCKER_ORG:-ghcr.io/mailu}/${DOCKER_PREFIX:-}radicale:${MAILU_VERSION:-{{ version }}}
     restart: always
+    logging:
+      driver: journald
+      options:
+        tag: mailu-webdav
     volumes:
       - "{{ root }}/dav:/data"
     networks:
@@ -248,6 +256,10 @@ services:
     image: ${DOCKER_ORG:-ghcr.io/mailu}/${DOCKER_PREFIX:-}fetchmail:${MAILU_VERSION:-{{ version }}}
     restart: always
     env_file: {{ env }}
+    logging:
+      driver: journald
+      options:
+        tag: mailu-fetchmail
     volumes:
       - "{{ root }}/data/fetchmail:/data"
     depends_on:
@@ -267,6 +279,10 @@ services:
     image: ${DOCKER_ORG:-ghcr.io/mailu}/${DOCKER_PREFIX:-}webmail:${MAILU_VERSION:-{{ version }}}
     restart: always
     env_file: {{ env }}
+    logging:
+      driver: journald
+      options:
+        tag: mailu-webmail
     volumes:
       - "{{ root }}/webmail:/data"
       - "{{ root }}/overrides/{{ webmail_type }}:/overrides:ro"

towncrier/newsfragments/2939.bugfix

@@ -0,0 +1,4 @@
+Fixed log filter not filtering out log messages for dovecot/nginx/postfix.
+Fixed postfix not logging to standard out.
+Fixed not all containers logging to journald.
+Removed POSTFIX_LOG_FILE functionality. Added documentation on how to achieve the same (log to file) via journald & rsyslogd (see new FAQ entry 'How can I view and export the logs of a Mailu container?').