Prefix all log messages with msgid (Postfix queue_id) if available

Author: onlime

.env.docker

@@ -12,6 +12,6 @@ SOCKET="0.0.0.0,10033"
 # SOCKET=/tmp/test.sock
 LOG_LEVEL=DEBUG
 # LOG_FILE=/tmp/policyd-rate-guard.log
-# LOG_MSG_PREFIX=True
+# LOG_MSG_PREFIX=False
 LOG_CONSOLE=True
 # SYSLOG=True

.env.example

@@ -15,7 +15,7 @@ DB_DATABASE=policyd-rate-guard
 # SOCKET="[::1],10033" # Use this for IPv6 TCP socket
 # LOG_LEVEL=INFO # DEBUG, INFO, WARNING, ERROR, CRITICAL
 # LOG_FILE=/var/log/policyd-rate-guard/policyd-rate-guard.log
-# LOG_MSG_PREFIX=True # True or False (default: True) - Prefix log messages with caller filename and class/method
+LOG_MSG_PREFIX=False # True or False (default: True) - Prefix log messages with caller filename and class/method
 LOG_CONSOLE=True # True or False (default: False) - Output logs to console (stderr)
 # SYSLOG=True # True or False (default: False) - Send logs to syslog
 # SENTRY_DSN=https://**********.ingest.sentry.io/XXXXXXXXXXXXXXXX # Your Sentry DSN (default: None)

.env.github

@@ -12,6 +12,6 @@ SOCKET="127.0.0.1,10033"
 # SOCKET=/tmp/test.sock
 LOG_LEVEL=ERROR
 # LOG_FILE=/tmp/policyd-rate-guard.log
-# LOG_MSG_PREFIX=True
+# LOG_MSG_PREFIX=False
 LOG_CONSOLE=True
 # SYSLOG=True

.env.test

@@ -11,7 +11,7 @@ DB_DATABASE=policyd-rate-guard
 SOCKET="127.0.0.1,10033"
 LOG_LEVEL=ERROR
 # LOG_FILE=/tmp/policyd-rate-guard.log
-# LOG_MSG_PREFIX=True
+# LOG_MSG_PREFIX=False
 LOG_CONSOLE=True
 # SYSLOG=True
 # SENTRY_DSN=https://**********.ingest.sentry.io/XXXXXXXXXXXXXXXX

CHANGELOG.md

@@ -4,7 +4,8 @@
 
 **Added:**
 
-- Added `LOG_MSG_PREFIX` (boolean) environment variable which is enabled by default. Prefix all log messages with a prefix containing information about the calling filename, class, and function name, e.g. `ratelimit.py Ratelimit.update() - `. 
+- Added `LOG_MSG_PREFIX` (boolean) environment variable which is enabled by default. Prefix all log messages with a prefix containing information about the calling filename, class, and function name, e.g. `ratelimit.py Ratelimit.update() - `.
+- Always prepend log messages with message ID (Postfix `queue_id`) if available, independent from `LOG_MSG_PREFIX` feature being enabled/disabled.
 
 **Fixed:**
 

README.md

@@ -209,7 +209,7 @@ PolicydRateGuard can be fully configured through environment variables in `.env`
 - `LOG_FILE`
   Set a logfile path, e.g. `/var/log/policyd-rate-guard/policyd-rate-guard.log`. This can be used in addition to enabling `SYSLOG` and/or `LOG_CONSOLE`, to log into a separate log file. Defaults to `None` (commented out).
 - `LOG_MSG_PREFIX`
-  Prefix all log messages with a prefix containing information about the calling filename, class, and function name, e.g. `ratelimit.py Ratelimit.update() - `. Defaults to `True`.
+  Prefix all log messages with a prefix containing information about the calling filename, class, and function name, e.g. `ratelimit.py Ratelimit.update() - `. We recommend to disable this on a production deployment (as it's more kind of debug information that shouldn't bloat our logs). Defaults to `True`.
 - `LOG_CONSOLE` (bool)
   Send logs to console (on `stderr`). This can be used in addition to enabling `LOG_FILE` and/or `SYSLOG`. Possible values: `True` or `False`. Defaults to `False`.
 - `SYSLOG` (bool)

app/handler.py

@@ -9,7 +9,7 @@ def __init__(self, conn: object, addr: str, conf: object, logger: object, db: ob
         self.conn = conn
         self.addr = addr
         self.conf = conf
-        self.logger = logger # TODO: Add msgid to logger
+        self.logger = logger
         self.db = db
         try:
             self.handle()
@@ -39,6 +39,9 @@ def handle(self):
             except ValueError: # Needed to ignore lines without "=" (e.g. the final two empty lines)
                 pass
 
+        # Add msgid to logger
+        self.logger.msgid = request.get('queue_id')
+
         # Break no sasl_username was found (e.g. on incoming mail on port 25)
         if not request.get('sasl_username'):
             self.logger.debug('sasl_username is empty, accepting message and reply with DUNNO')
@@ -77,8 +80,7 @@ def handle(self):
 
         # Detailed log message in the following format:
         # TEST1234567: client=unknown[8.8.8.8], helo=myCLIENTPC, sasl_method=PLAIN, sasl_username=test@example.com, recipient_count=1, curr_count=2/1000, status=ACCEPTED
-        log_message = '{}: client={}[{}], helo={}, sasl_method={}, sasl_username={}, from={}, to={}, recipient_count={}, curr_count={}/{}, status={}{}'.format(
-            message.msgid,
+        log_message = 'client={}[{}], helo={}, sasl_method={}, sasl_username={}, from={}, to={}, recipient_count={}, curr_count={}/{}, status={}{}'.format(
             message.client_name,
             message.client_address,
             request.get('helo_name'), # currently not stored in Message object or `messages` table
@@ -105,6 +107,7 @@ def handle(self):
             self.send_response('OK')
             self.logger.info(log_message)
 
+        self.logger.msgid = None # Reset msgid in logger
         self.conn.close()
 
     def send_response(self, message: str = 'OK'):

app/logging.py

@@ -5,12 +5,22 @@
 from os import path
 
 class PrefixedLogger(logging.Logger):
+    """Custom logger that prefixes messages with msgid, the filename, class and function name of the caller"""
+
+    msg_prefix = True
+    msgid = None
+
     def __init__(self, name, level=logging.NOTSET):
         super().__init__(name, level)
 
     def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False):
-        co_filename, co_class, co_function = self._get_caller_info()
-        prefix = f"{path.basename(co_filename)} {co_class}.{co_function}() - "
+        if self.msg_prefix:
+            co_filename, co_class, co_function = self._get_caller_info()
+            prefix = f"{path.basename(co_filename)} {co_class}.{co_function}() - "
+        else:
+            prefix = ''
+        if self.msgid:
+            prefix += f"{self.msgid}: "
         msg = prefix + msg
         super()._log(level, msg, args, exc_info, extra, stack_info)
 
@@ -60,10 +70,10 @@ def get_logger(conf: Config):
         log_handlers.append(syslog)
 
     # Set the custom logger class
-    if conf.get('LOG_MSG_PREFIX', True):
-        logging.setLoggerClass(PrefixedLogger)
+    logging.setLoggerClass(PrefixedLogger)
     logging.basicConfig(level=log_level, format=log_format, handlers=log_handlers)
     logger = logging.getLogger('policyd-rate-guard')
     logger.setLevel(log_level)
+    logger.msg_prefix = conf.get('LOG_MSG_PREFIX', True) # Enable/disable custom log message prefix feature
 
     return logger

app/message.py

@@ -74,5 +74,5 @@ def is_blocked(self) -> bool:
         self.blocked = False
         return False
 
-    def get_props_description(self, props: list = ['msgid', 'sender', 'rcpt_count', 'from_addr', 'client_address', 'client_name'], separator: str = ' '):
+    def get_props_description(self, props: list = ['sender', 'rcpt_count', 'from_addr', 'client_address', 'client_name'], separator: str = ' '):
         return separator.join(f"{name}={getattr(self, name)}" for name in props)

tests/test_app_message.py

@@ -68,7 +68,7 @@ def test_store(self) -> None:
 
     def test_get_props_description(self) -> None:
         desc = self.message.get_props_description()
-        self.assertEqual(desc, 'msgid=TEST1234567 sender=test@example.com rcpt_count=3 from_addr=test@example.com client_address=172.19.0.2 client_name=unknown')
+        self.assertEqual(desc, 'sender=test@example.com rcpt_count=3 from_addr=test@example.com client_address=172.19.0.2 client_name=unknown')
         desc = self.message.get_props_description(['msgid'])
         self.assertEqual(desc, 'msgid=TEST1234567')
         desc = self.message.get_props_description(['msgid', 'sender', 'rcpt_count'])