Merge pull request #38 from mbengit/master

mbengit · web-flow · commit 16800727e975 · 2020-09-11T16:55:09.000+01:00
Refactor log handling
diff --git a/README.md b/README.md
@@ -14,6 +14,9 @@ The qpylib library hosted here is for use only with apps that have been written
 Python 3 to run on Red Hat Universal Base Image. It is not compatible with apps
 written to run on a CentOS base image.
 
+Most functions are the equivalent of their pre-Github counterparts, although
+there may be some small differences in parameter names.
+
 ## Project details
 
 * [LICENSE](LICENSE)
diff --git a/qpylib/encryption/cryptoutil.py b/qpylib/encryption/cryptoutil.py
@@ -0,0 +1,15 @@
+# Copyright 2019 IBM Corporation All Rights Reserved.
+#
+# SPDX-License-Identifier: Apache-2.0
+
+from cryptography.hazmat.backends import default_backend
+from cryptography.hazmat.primitives import hashes
+from cryptography.hazmat.primitives.kdf.pbkdf2 import PBKDF2HMAC
+
+def derive_key(key_material, salt, iterations=100000, length=32):
+    kdf = PBKDF2HMAC(algorithm=hashes.SHA256(),
+                     length=length,
+                     salt=salt,
+                     iterations=iterations,
+                     backend=default_backend())
+    return kdf.derive(key_material)
diff --git a/qpylib/encryption/enginev4.py b/qpylib/encryption/enginev4.py
@@ -6,9 +6,7 @@
 import string
 import secrets
 from cryptography.fernet import Fernet
-from cryptography.hazmat.backends import default_backend
-from cryptography.hazmat.primitives import hashes
-from cryptography.hazmat.primitives.kdf.pbkdf2 import PBKDF2HMAC
+from . import cryptoutil
 
 class Enginev4():
     ''' Enginev4 uses Fernet encryption.
@@ -30,14 +28,9 @@ def decrypt(self):
         return decrypted_bytes.decode('utf-8')
 
     def _derive_key(self):
-        kdf = PBKDF2HMAC(
-            algorithm=hashes.SHA256(),
-            length=32,
-            salt=self.config['salt'].encode('utf-8'),
-            iterations=self.config['iterations'],
-            backend=default_backend()
-        )
-        key = kdf.derive(self.app_uuid.encode('utf-8'))
+        key = cryptoutil.derive_key(self.app_uuid.encode('utf-8'),
+                                    self.config['salt'].encode('utf-8'),
+                                    self.config['iterations'])
         return base64.urlsafe_b64encode(key)
 
     @staticmethod
diff --git a/qpylib/log_qpylib.py b/qpylib/log_qpylib.py
@@ -4,74 +4,160 @@
 
 import logging
 from logging.handlers import RotatingFileHandler, SysLogHandler
-from . import app_qpylib
-from . import util_qpylib
+import re
+from qpylib.encryption.cryptoutil import derive_key
+from . import app_qpylib, util_qpylib
 
-APP_FILE_LOG_FORMAT = '%(asctime)s [%(module)s.%(funcName)s] [%(threadName)s] [%(levelname)s] - %(message)s'
-APP_CONSOLE_LOG_FORMAT = '%(asctime)s %(module)s.%(funcName)s: %(message)s'
+# Log format for local file logging.
+# Uses default date/time formatting from logging module.
+# Before the logging formatter is created, APPID is substituted with the actual app ID,
+# which is constant for all logs generated within an app container.
+# Example: 2020-08-19 12:48:11,423 [Thread-4] [INFO] [APP_ID:1005] [NOT:0000006000] hello
 
-QLOGGER = 0
+APP_FILE_LOG_FORMAT = '%(asctime)s [%(threadName)s] [%(levelname)s] [APP_ID:APPID] [NOT:%(ncode)s] %(message)s'
 
-def log(message, level):
-    log_fn = _choose_log_fn(level)
-    log_fn("[APP_ID/{0}][NOT:{1}] {2}"
-           .format(app_qpylib.get_app_id(), _map_notification_code(level), message))
+# Log format for Syslog.
+# See https://tools.ietf.org/html/rfc5424 for more details on the following specification:
+# SYSLOG-MSG = HEADER SP STRUCTURED-DATA SP MSG
+# HEADER = PRI VERSION SP TIMESTAMP SP HOSTNAME SP APPNAME SP PROCID SP MSGID
+# PRI is taken care of by SysLogHandler and not included in the log format below.
+# VERSION is hard-coded to 1.
+# TIMESTAMP in the specification is e.g. 2020-04-12T19:20:50.345678+01:00
+#   Seconds fraction is not supported in "time" module, which is what the logging
+#   module uses. SYSLOG_LOG_FORMAT uses asctime formatted with SYSLOG_TIME_FORMAT.
+# HOSTNAME is set to a hash generated using the app ID and QRADAR_APP_UUID.
+#   The reason for not using the container host name or IP address is that for a
+#   given app instance, both of those values can change across a reboot.
+# APPNAME is set to a sanitised copy of the app manifest name field.
+# PROCID is set to the app ID.
+#   HOSTNAME, APPNAME and PROCID are all constants, replaced in the format string with their values.
+# MSGID and STRUCTURED-DATA are set to the Syslog nil value '-'.
+# Example: <14>1 2020-08-21T14:16:51+0100 d15fbd9fdd86b30e MyExampleApp 1005 - - [NOT:0000006000] hello
+
+SYSLOG_LOG_FORMAT = '1 %(asctime)s HOSTNAME APPNAME PROCID - - [NOT:%(ncode)s] %(message)s'
+SYSLOG_TIME_FORMAT = '%Y-%m-%dT%H:%M:%S%z'
+
+# Globals related to logging.Logger instance.
+QLOGGER = None
+LOG_LEVEL_TO_FUNCTION = None
 
 def create_log():
     global QLOGGER
     QLOGGER = logging.getLogger('com.ibm.applicationLogger')
-    QLOGGER.setLevel(default_log_level())
+    QLOGGER.setLevel(_default_log_level())
+    QLOGGER.addFilter(NotificationCodeFilter())
 
-    handler = RotatingFileHandler(_log_file_location(), maxBytes=2*1024*1024, backupCount=5)
-    handler.setFormatter(logging.Formatter(APP_FILE_LOG_FORMAT))
-    QLOGGER.addHandler(handler)
+    for handler in _generate_handlers():
+        QLOGGER.addHandler(handler)
 
-    if not util_qpylib.is_sdk():
-        console_ip = app_qpylib.get_console_ip()
-        if util_qpylib.is_ipv6_address(console_ip):
-            console_ip = console_ip[1:-1]
-        syslog_handler = SysLogHandler(address=(console_ip, 514))
-        syslog_handler.setFormatter(logging.Formatter(APP_CONSOLE_LOG_FORMAT))
-        QLOGGER.addHandler(syslog_handler)
+    global LOG_LEVEL_TO_FUNCTION
+    LOG_LEVEL_TO_FUNCTION = {
+        'DEBUG': QLOGGER.debug,
+        'INFO': QLOGGER.info,
+        'WARNING': QLOGGER.warning,
+        'ERROR': QLOGGER.error,
+        'EXCEPTION': QLOGGER.exception,
+        'CRITICAL': QLOGGER.critical
+    }
+
+def log(message, level):
+    global LOG_LEVEL_TO_FUNCTION
+    if not LOG_LEVEL_TO_FUNCTION:
+        raise RuntimeError('You cannot use log before logging has been initialised')
+    log_function = LOG_LEVEL_TO_FUNCTION.get(level.upper())
+    if not log_function:
+        raise ValueError("Unknown level: '{0}'".format(level))
+    log_function(message)
 
 def set_log_level(level='INFO'):
     global QLOGGER
-    QLOGGER.setLevel(_map_log_level(level))
+    if not QLOGGER:
+        raise RuntimeError('You cannot use set_log_level before logging has been initialised')
+    QLOGGER.setLevel(level.upper())
 
-def default_log_level():
-    return _map_log_level(app_qpylib.get_manifest_field_value('log_level', 'INFO'))
+def _default_log_level():
+    return app_qpylib.get_manifest_field_value('log_level', 'INFO').upper()
 
 def _log_file_location():
     return app_qpylib.get_log_path('app.log')
 
-def _choose_log_fn(level):
-    global QLOGGER
-    if QLOGGER == 0:
-        raise RuntimeError('You cannot use log before logging has been initialised')
-    return {
-        'INFO': QLOGGER.info,
-        'DEBUG': QLOGGER.debug,
-        'WARNING': QLOGGER.warning,
-        'ERROR': QLOGGER.error,
-        'EXCEPTION': QLOGGER.exception,
-        'CRITICAL': QLOGGER.critical
-    }.get(level.upper(), QLOGGER.info)
-
-def _map_notification_code(level):
-    return {
-        'INFO': "0000006000",
-        'DEBUG': "0000006000",
-        'WARNING': "0000004000",
-        'ERROR': "0000003000",
-        'EXCEPTION': "0000003000",
-        'CRITICAL': "0000003000"
-    }.get(level.upper(), "0000006000")
-
-def _map_log_level(level):
-    return {
-        'INFO': logging.INFO,
-        'DEBUG': logging.DEBUG,
-        'WARNING': logging.WARNING,
-        'ERROR': logging.ERROR,
-        'CRITICAL': logging.CRITICAL
-    }.get(level.upper(), logging.INFO)
+def _generate_handlers():
+    handlers = []
+
+    app_id = str(app_qpylib.get_app_id())
+    handlers.append(_create_file_handler(app_id))
+
+    address = None
+    qradar_app_uuid = None
+    try:
+        address = _get_address_for_syslog()
+        qradar_app_uuid = app_qpylib.get_env_var('QRADAR_APP_UUID')
+    except KeyError:
+        pass
+    if address and qradar_app_uuid:
+        handlers.append(_create_syslog_handler(address, app_id, qradar_app_uuid))
+
+    return handlers
+
+def _create_file_handler(app_id):
+    handler = RotatingFileHandler(_log_file_location(), maxBytes=2*1024*1024, backupCount=5)
+    log_format = APP_FILE_LOG_FORMAT.replace('APPID', app_id)
+    handler.setFormatter(logging.Formatter(log_format))
+    return handler
+
+def _create_syslog_handler(syslog_address, app_id, qradar_app_uuid):
+    log_format = _create_syslog_log_format(app_id, qradar_app_uuid)
+    handler = SysLogHandler(address=syslog_address)
+    handler.setFormatter(logging.Formatter(log_format, SYSLOG_TIME_FORMAT))
+    return handler
+
+def _get_address_for_syslog():
+    console_ip = app_qpylib.get_console_ip()
+    if util_qpylib.is_ipv6_address(console_ip):
+        console_ip = console_ip[1:-1]
+    return (console_ip, 514)
+
+def _create_syslog_log_format(app_id, qradar_app_uuid):
+    pseudo_hostname = _create_pseudo_hostname(app_id, qradar_app_uuid)
+    sanitized_app_name = _create_sanitized_app_name()
+    return SYSLOG_LOG_FORMAT.replace('HOSTNAME', pseudo_hostname) \
+                            .replace('APPNAME', sanitized_app_name) \
+                            .replace('PROCID', app_id)
+
+def _create_pseudo_hostname(app_id, qradar_app_uuid):
+    # This uses a key derivation function rather than a straightforward hash
+    # function so that the unique value generated has 16 characters (hex).
+    # Anything longer would occupy too much space in each log record.
+    key = derive_key(app_id.encode('utf-8'),
+                     qradar_app_uuid.encode('utf-8'),
+                     length=8)
+    return key.hex()
+
+def _create_sanitized_app_name():
+    ''' Extracts app name from manifest, strips unwanted characters,
+        and truncates to max length 48, as per RFC5424.
+    '''
+    return re.sub(r'\W+', '', app_qpylib.get_app_name())[:48]
+
+class NotificationCodeFilter(logging.Filter):
+    ''' Filter which adds a field named ncode to each log record.
+        Allows notification code to be specified in log handler
+        format strings.
+    '''
+    # These are standard QRadar codes for identifying log levels.
+    Q_INFO_CODE = '0000006000'
+    Q_WARNING_CODE = '0000004000'
+    Q_ERROR_CODE = '0000003000'
+
+    def filter(self, record):
+        record.ncode = self._log_level_to_notification_code.get(
+            record.levelname.upper(), self.Q_INFO_CODE)
+        return True
+
+    _log_level_to_notification_code = {
+        'DEBUG': Q_INFO_CODE,
+        'INFO': Q_INFO_CODE,
+        'WARNING': Q_WARNING_CODE,
+        'ERROR': Q_ERROR_CODE,
+        'CRITICAL': Q_ERROR_CODE
+    }
diff --git a/qpylib/qpylib.py b/qpylib/qpylib.py
@@ -12,23 +12,34 @@
 
 # ==== Logging ====
 
+def create_log():
+    ''' Initialises logging.
+        Threshold log level is set to the value of the "log_level" field
+        in the app manifest.json, or INFO if that field is absent.
+        Creates a file log handler which directs logs to store/log/app.log.
+        Creates a Syslog handler, but only if environment variables
+        QRADAR_CONSOLE_IP and QRADAR_APP_UUID are both set.
+        Must be called before any call to log() or set_log_level().
+        Raises ValueError if the manifest threshold log level is invalid.
+    '''
+    log_qpylib.create_log()
+
 def log(message, level='INFO'):
     ''' Logs a message at the given level, which defaults to INFO.
-        Level values: DEBUG, INFO, WARNING, ERROR, CRITICAL.
+        Level values: DEBUG, INFO, WARNING, ERROR, EXCEPTION, CRITICAL.
+        EXCEPTION is ERROR plus extra exception details.
         Raises RuntimeError if logging was not previously initialised
         by a call to qpylib.create_log().
+        Raises ValueError if level is invalid.
     '''
     log_qpylib.log(message, level)
 
-def create_log():
-    ''' Initialises logging with INFO as the threshold log level.
-        Must be called before any call to qpylib.log().
-    '''
-    log_qpylib.create_log()
-
 def set_log_level(level):
     ''' Sets the threshold log level.
         Level values: DEBUG, INFO, WARNING, ERROR, CRITICAL.
+        Raises RuntimeError if logging was not previously initialised
+        by a call to qpylib.create_log().
+        Raises ValueError if level is invalid.
     '''
     log_qpylib.set_log_level(level)
 
diff --git a/test/test_logging.py b/test/test_logging.py
