Fault Management API request audit logging

Here is added a hook to the WSGI compliant Pecan server that receives
the Fault Management API requests. This hook logs the needed request
data to "/var/log/fm-api.log". All requests are logged except the
ones of "GET" type.

The code is a port from the same hook that exists in
"starlingx/config" repository, also called "AuditLogging".

Note: there are no "POST" or "PUT" requests available in Fault
Management API v1.

Test Plan:

PASS: Successfully deploy an AIO-SX and verify that the logs of
"fm-api" service are present in file "/var/log/fm-api.log".
PASS: In the deployed AIO-SX, execute command "fm alarm-list" and
check that no GET requests was logged in "fm-api.log".
PASS: In the deployed AIO-SX, execute command "fm alarm-delete 1111"
and check that a "DELETE /v1/alarms/1111" request was logged in
"fm-api.log" with status "404".
PASS: In the deployed AIO-SX, execute command
"fm event-suppress --alarm_id <alarm_id>" and check that a
"PATCH /v1/event_suppression/<uuid>" request was logged in
"fm-api.log" with status "200".
PASS: Successfully build all packages of this repository as Debian
packages: fm-api, fm-common, fm-doc, fm-mgr, fm-rest-api and
python-fmclient.

Story: 2009824
Task: 44468

Depends-On: https://review.opendev.org/c/starlingx/config-files/+/828200
Signed-off-by: Joao Victor Portal <Joao.VictorPortal@windriver.com>
Change-Id: I25bf662ed9e792b30ae1f90329bd35b918f0a5f7

fm-mgr/sources/fm.logrotate

@@ -4,6 +4,21 @@
 # SPDX-License-Identifier: Apache-2.0
 #
 
+/var/log/fm-api.log
+{
+    create 0640 root root
+    size 10M
+    start 1
+    rotate 20
+    missingok
+    compress
+    sharedscripts
+    postrotate
+        systemctl reload syslog-ng > /dev/null 2>&1 || true
+    endscript
+    delaycompress
+}
+
 /var/log/fm-event.log
 {
     create 0640 root root

fm-rest-api/fm/fm/api/config.py

@@ -1,5 +1,5 @@
 #
-# Copyright (c) 2018 Wind River Systems, Inc.
+# Copyright (c) 2018, 2022 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
@@ -43,6 +43,7 @@ app = {
     'hooks': [
         hooks.ContextHook(),
         hooks.DBHook(),
+        hooks.AuditLogging(),
     ],
     'acl_public_routes': [
         '/',
@@ -65,6 +66,9 @@ def init(args, **kwargs):
 
 def setup_logging():
     """Sets up the logging options for a log with supplied name."""
+    extra_log_level_defaults = ['eventlet.wsgi.server=WARN']
+    logging.set_defaults(default_log_levels=logging.get_default_log_levels() +
+                         extra_log_level_defaults)
     logging.setup(cfg.CONF, "fm")
     LOG.debug("Logging enabled!")
     LOG.debug("%(prog)s version %(version)s",

fm-rest-api/fm/fm/api/hooks.py

@@ -1,14 +1,18 @@
 #
-# Copyright (c) 2018 Wind River Systems, Inc.
+# Copyright (c) 2018, 2022 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
 
+import re
+import time
+from six.moves.urllib.parse import urlparse
 import webob
 from pecan import hooks
 from oslo_config import cfg
 from oslo_log import log
 from oslo_serialization import jsonutils
+from oslo_utils import uuidutils
 
 from fm.common import context
 from fm.db import api as dbapi
@@ -18,6 +22,13 @@ CONF = cfg.CONF
 
 LOG = log.getLogger(__name__)
 
+audit_log_name = "{}.{}".format(__name__, "auditor")
+auditLOG = log.getLogger(audit_log_name)
+
+
+def generate_request_id():
+    return 'req-%s' % uuidutils.generate_uuid()
+
 
 class ContextHook(hooks.PecanHook):
     """Configures a request context and attaches it to the request.
@@ -86,3 +97,101 @@ class DBHook(hooks.PecanHook):
 
     def before(self, state):
         state.request.dbapi = dbapi.get_instance()
+
+
+class AuditLogging(hooks.PecanHook):
+    """
+        Performs audit logging of all Fault Manager
+        ["POST", "PUT", "PATCH", "DELETE"] REST requests.
+    """
+
+    def __init__(self):
+        self.log_methods = ["POST", "PUT", "PATCH", "DELETE"]
+
+    def before(self, state):
+        state.request.start_time = time.time()
+
+    def __after(self, state):
+
+        method = state.request.method
+        if method not in self.log_methods:
+            return
+
+        now = time.time()
+        try:
+            elapsed = now - state.request.start_time
+        except AttributeError:
+            LOG.info("Start time is not in request, setting it to 0.")
+            elapsed = 0
+
+        environ = state.request.environ
+        server_protocol = environ["SERVER_PROTOCOL"]
+
+        response_content_length = state.response.content_length
+
+        user_id = state.request.headers.get('X-User-Id')
+        user_name = state.request.headers.get('X-User', user_id)
+        tenant_id = state.request.headers.get('X-Tenant-Id')
+        tenant = state.request.headers.get('X-Tenant', tenant_id)
+        domain_name = state.request.headers.get('X-User-Domain-Name')
+        try:
+            request_id = state.request.context.request_id
+        except AttributeError:
+            LOG.info("Request id is not in request, setting it to an "
+                     "auto generated id.")
+            request_id = generate_request_id()
+
+        url_path = urlparse(state.request.path_qs).path
+
+        def json_post_data(rest_state):
+            if 'form-data' in rest_state.request.headers.get('Content-Type'):
+                return " POST: {}".format(rest_state.request.params)
+            if not hasattr(rest_state.request, 'json'):
+                return ""
+            return " POST: {}".format(rest_state.request.json)
+
+        # Filter password from log
+        filtered_json = re.sub(r'{[^{}]*(passwd_hash|community|password)[^{}]*},*',
+                               '',
+                               json_post_data(state))
+
+        log_data = \
+            "{} \"{} {} {}\" status: {} len: {} time: {}{} host:{}" \
+            " agent:{} user: {} tenant: {} domain: {}".format(
+                state.request.remote_addr,
+                state.request.method,
+                url_path,
+                server_protocol,
+                state.response.status_int,
+                response_content_length,
+                elapsed,
+                filtered_json,
+                state.request.host,
+                state.request.user_agent,
+                user_name,
+                tenant,
+                domain_name)
+
+        # The following ctx object will be output in the logger as
+        # something like this:
+        # [req-088ed3b6-a2c9-483e-b2ad-f1b2d03e06e6
+        #  3d76d3c1376744e8ad9916a6c3be3e5f
+        #  ca53e70c76d847fd860693f8eb301546]
+        # When the ctx is defined, the formatter (defined in common/log.py) requires that keys
+        # request_id, user, tenant be defined within the ctx
+        ctx = {'request_id': request_id,
+               'user': user_id,
+               'tenant': tenant_id}
+
+        auditLOG.info("{}".format(log_data), context=ctx)
+
+    def after(self, state):
+        try:
+            self.__after(state)
+        except Exception:
+            # Logging and then swallowing exception to ensure
+            # rest service does not fail even if audit logging fails
+            auditLOG.exception("Exception in AuditLogging on event 'after'")
+
+    def on_error(self, state, e):
+        auditLOG.exception("Exception in AuditLogging passed to event 'on_error': " + str(e))

fm-rest-api/fm/scripts/fm-api.service

@@ -1,6 +1,6 @@
 [Unit]
 Description=Fault Management REST API Service
-After=nfscommon.service sw-patch.service
+After=nfscommon.service sw-patch.service syslog-ng.service
 After=network-online.target systemd-udev-settle.service
 
 [Service]