Task/add access matches (about users, headers, path. .. ) to access Logger

CHANGES_NEXT_RELEASE

@@ -1,2 +1,6 @@
+- Add: user name, request path, query and body to AccessLogger (#541)
+- Add: Access Logger Patterns to match to Access Logger (#541)
+- Fix: ensure Origin of AccesLogger show x-forwarderd-for header if exists
+- Fix: Homogenizes format for Access Logger with pep logs
 - Upgrade body-parser dep from 1.20.0 to 1.20.3
 - Upgrade express from 4.19.2 to 4.20.0

README.md

@@ -25,7 +25,7 @@
 * [Development documentation](#development)
 
 ## <a name="overview"/> Overview
-The Orion Policy Enforcement Point (PEP) is a proxy meant to secure independent FiWare components, by intercepting every request sent to the component, validating it against the Access Control component. This validation is based in several pieces of data:
+The Policy Enforcement Point (PEP) is a proxy meant to secure independent FiWare components, by intercepting every request sent to the component, validating it against the Access Control component. This validation is based in several pieces of data:
 
 * User token: comes from the OAuth authorization server and is taken from the `x-auth-token` header.
 * ServiceId: is read from the `fiware-service` header and identifies the protected component.
@@ -439,23 +439,80 @@ In order to have the proxy running, there are several basic pieces of informatio
     port: 7070,
     path: '/pdp/v3',
     account: false,
-    accountFile: '/tmp/pepAccount.log'
+    accountFile: '/tmp/pepAccount.log',
+    accountMode: 'all'
 }
 ```
-Accounting log is only activated when account flag is true, and the logs are produced in a fixed INFO level for accountLogger, redardless of the pep log level.
-Note that accunting log is not rotate, so you should make sure you configure your own rotation system.
-Accounting access log include daba about:
+Accounting log is only activated when account flag is true, and the logs are produced in a fixed INFO level for accessLogger, redardless of the pep log level.
+Note that accounting log is not rotated, so you should make sure you configure your own rotation system.
+Accounting access log include data about:
 * Attempt was right or not
 * Token
 * Origin
 * UserId
+* UserName
 * ServiceId
+* Service
 * SubServiceId
+* SubService
 * Action
+* Path
+* Body
 * Date
+* Query
 Example of access log:
 ```
-Right Attempt | ResponseStatus=200 | Token=860864fb6d1a4c8a8cb7d59d16daaa52 | Origin=192.168.1.125 | UserId=62c63ada8694451fb67a341346172499 | ServiceId=a9b38dd2a97e4944b2daebdb74ed60ff | Service=smartgondor | SubServiceId=/ | SubService=/ | Action=read | Date=2017-09-21T12:46:57.844Z
+"Right Attempt | ResponseStatus=200 | Token=gAAAAABnBPgPrgwpcAkbQOZIryu5ADUIScyorN3vbPYbTJxTE5AF3RO1y25Tf-sL3EKzvfr_1U3u8IL8ylB4e4B_vD5yZjc9rnrSIqoiC77B7uZ1O1xZCyukq_MkjRxJLqA9yQ5lQtAQCC6ig7Kn5uPhpPD-mhVb7kyQjUw1QjtCiyP7UKXZvKU | Origin=172.17.0.22 | UserId=753b954985bf460fabbd6953c71d50c7 | UserName=adm1 | ServiceId=9f710408f5944c3993db600810e97c83 | Service=smartcity | SubServiceId=/ | SubService=/ | Action=read | Path=/v2/entities | Query={\"limit\":\"15\",\"offset\":\"0\",\"options\":\"count\"} | Body={} | Date=2024-10-08T09:25:30.441Z"
+```
+
+Note that the above format is not the same than the regular PEP log (although it is also based in fields separated by `|`, the fields themselves are not the same).
+
+Additionally a file configAccessMatch could be provided to pep to check matches about some elements involved in current access, regardless is right or not right access. For example:
+* List for users involved
+* List of headers and values
+* List of subpaths in URL request
+* List of subqueries in query request
+* List of strings in body
+
+PEP reloads this file each time it changes without needing restarting PEP itself.
+
+This is an example of file `configAccessMatch.js` (full path `/opt/fiware-pep-steelskin/configAccessMatch.js` i.e. in a docker image):
+
+```
+// Activity related with a list of users
+configAccessMatch.users = [
+    'cracker1', 'cracker2',
+];
+
+// Activity related with request which the following headers
+configAccessMatch.headers = [
+    { "fiware-service": "smartcity" },
+    { "x-real-ip": "127.0.0.1" }
+];
+
+// Activity related with request including the following subpaths
+configAccessMatch.subpaths = [
+    '/v1',
+];
+
+// Activity related with request including the following subqueries
+configAccessMatch.subqueries = [
+    'flowControl', 'options',
+];
+
+// Activity related with request including the following strings in body
+configAccessMatch.body = [
+    'legacy',
+];
+```
+
+When any of theses patterns matches in current access, message access is added with `MATCHED <element> <value>` , where `<element>` would be: `USER`, `HEADER <header-name>`, `SUBPATH`, `SUBQUERY`, `BODY` and `<value>` the value which matches. For example:
+
+```
+Right Attempt MATCHED HEADER fiware-service smartcity | ResponseStatus=200 | Token=gAAAAABnBPgPrgwpcAkbQOZIryu5ADUIScyorN3vbPYbTJxTE5AF3RO1y25Tf-sL3EKzvfr_1U3u8IL8ylB4e4B_vD5yZjc9rnrSIqoiC77B7uZ1O1xZCyukq_MkjRxJLqA9yQ5lQtAQCC6ig7Kn5uPhpPD-mhVb7kyQjUw1QjtCiyP7UKXZvKU | Origin=172.17.0.22 | UserId=753b954985bf460fabbd6953c71d50c7 | UserName=adm1 | ServiceId=9f710408f5944c3993db600810e97c83 | Service=smartcity | SubServiceId=/ | SubService=/ | Action=read | Path=/v2/entities | Query={\"limit\":\"15\",\"offset\":\"0\",\"options\":\"count\"} | Body={} | Date=2024-10-08T09:25:30.441Z"
+```
+Account log has three modes: `all`, `matched`, `wrong`. First one `all` includes right and wrong access regardles if matches or not. Second one `matched` includes all wrong and just rigth matches acess. And `wrong` mode only includes all wrong access, regardless is matches or not with patterns.
+
 ```
 * `config.componentName`: name of the component that will be used to compose the FRN that will identify the resource to be accessed. E.g.: `orion`.
 * `config.resourceNamePrefix`: string prefix that will be used to compose the FRN that will identify the resource to be accessed. E.g.: `fiware:`.

bin/pepProxy

@@ -48,6 +48,7 @@ function loadConfiguration() {
         'ACCESS_PROTOCOL',
         'ACCESS_ACCOUNT',
         'ACCESS_ACCOUNTFILE',
+        'ACCESS_ACCOUNTMODE',
         'ADMIN_PORT',
         'AUTHENTICATION_HOST',
         'AUTHENTICATION_PORT',
@@ -103,6 +104,9 @@ function loadConfiguration() {
     if (process.env.ACCESS_ACCOUNTFILE) {
         config.access.accountFile = process.env.ACCESS_ACCOUNTFILE;
     }
+    if (process.env.ACCESS_ACCOUNTMODE) {
+        config.access.accountMode = process.env.ACCESS_ACCOUNTMODE;
+    }
     if (process.env.AUTHENTICATION_HOST) {
         config.authentication.options.host = process.env.AUTHENTICATION_HOST;
     }

config.js

@@ -64,7 +64,11 @@ config.access = {
     /**
      * Log Account file
      */
-    accountFile: '/tmp/pepAccount.log'
+    accountFile: '/tmp/pepAccount.log',
+    /**
+     * Account mode: `all`, `matched`, `wrong`
+     */
+    accountMode: 'all'
 };
 
 // User identity configuration

configAccessMatch.js

@@ -0,0 +1,35 @@
+'use strict';
+
+/**
+ * List of access match
+ */
+var configAccessMatch = {};
+
+// Activity related with a list of users
+configAccessMatch.users = [
+    // 'user1', 'user2',
+];
+
+// Activity related with request which the following headers
+configAccessMatch.headers = [
+    // { "fiware-service": "smartcity" },
+    // { "x-real-ip": "127.0.0.1" }
+];
+
+// Activity related with request including the following subpaths
+configAccessMatch.subpaths = [
+    // '/v1',
+];
+
+// Activity related with request including the following subqueries
+configAccessMatch.subqueries = [
+    // 'flowControl',
+];
+
+// Activity related with request including the following strings in body
+configAccessMatch.body = [
+    // 'legacy'
+];
+
+
+exports.configAccessMatch = configAccessMatch;

lib/constants.js

@@ -32,7 +32,8 @@ var constants = {
     X_REAL_IP_HEADER: 'x-real-ip',
     CORRELATOR_HEADER: 'fiware-correlator',
 
-    GET_ROLES_PATH: '/user'
+    GET_ROLES_PATH: '/user',
+    NA: 'N/A'
 };
 
 

lib/fiware-pep-steelskin.js

@@ -74,14 +74,22 @@ function handleError(error, req, res, next) {
  * @param {Function} next        Call to the next error handler in the chain.
  */
 function accountInfoError(error, req, res, next) {
-    accessLogger.info('Wrong Attempt' +
+    var accessMsg = 'Wrong Attempt';
+    accessMsg = proxyMiddleware.checkAccessMatches(req, accessMsg);
+    accessLogger.info(accessMsg +
                       ' | Error=' + error.name +
                       ' | Token=' + req.headers['x-auth-token'] +
-                      ' | Origin=' + req.connection.remoteAddress +
+                      ' | Origin=' + (req.ip || req.connection.remoteAddress) +
                       ' | UserId=' + req.userId +
+                      ' | ServiceId=' + req.serviceId +
+                      ' | UserName=' + req.userName +
                       ' | Service=' + req.service +
+                      ' | SubServiceId=' + req.subserviceId +
                       ' | SubService=' + req.subService +
                       ' | Action=' + req.action +
+                      ' | Path=' + req.path +
+                      ' | Query=' + JSON.stringify(req.query) +
+                      ' | Body=' + JSON.stringify(req.body) +
                       ' | Date=' + new Date().toJSON());
     next(error);
 }
@@ -114,10 +122,14 @@ function setAccessLogger() {
         level: 'info',
         transports: [
             new(winston.transports.File)({
-                filename: config.access.accountFile
+                filename: config.access.accountFile,
+                json: false,
+                timestamp: false,
+                showLevel: false
             })
         ]
     });
+    proxyMiddleware.watchConfigAccessMatchFile();
 }
 
 /**

lib/middleware/proxy.js

@@ -36,8 +36,30 @@ var config = require('../../config'),
         'x-auth-token'
     ],
     winston = require('winston'),
+    logger = require('logops'),
+    configAccessMatch = require('../../configAccessMatch.js').configAccessMatch,
     accessLogger;
 
+const fs = require('fs');
+const configAccessMatchFilePath = './configAccessMatch.js';
+
+function requireUncached(module) {
+    delete require.cache[require.resolve(module)];
+    return require(module);
+}
+
+function watchConfigAccessMatchFile() {
+    fs.watch(configAccessMatchFilePath, (event, filename) => {
+        logger.info('watchConfigAccessMatchFile changed by %s detected in file %s', event, filename);
+        try {
+            configAccessMatch = requireUncached('../../configAccessMatch.js').configAccessMatch;
+            logger.debug('reloaded configAccessMatch %j', configAccessMatch);
+        } catch (err) {
+            logger.error('Error %s reloading module: %s ', err, filename);
+        }
+    });
+}
+
 /**
  * Middleware to extract the organization data from the request.
  *
@@ -175,6 +197,44 @@ function sendRequest(req, res, next) {
     next();
 }
 
+/**
+ * Check here MATCH file patterns
+ *
+ * @param {Object} req           Incoming request.
+ * @param {String} accessMsg     Incoming accessMsg
+ * @return {String}              String message corresponding with accessMsg and found matches
+ */
+function checkAccessMatches(req, accessMsg) {
+    if (req.userName in configAccessMatch.users ) {
+        accessMsg += ' MATCHED USER ' + req.userName;
+    }
+    for (var header of configAccessMatch.headers) {
+        var headerName = Object.keys(header)[0];
+        if (Object.keys(req.headers).includes(headerName)) {
+            if (req.headers[headerName] === header[headerName]) {
+                accessMsg += ' MATCHED HEADER ' + headerName + ' ' + header[headerName];
+            }
+        }
+    }
+    for (var subpath of configAccessMatch.subpaths) {
+        if (req.path.includes(subpath)) {
+            accessMsg += ' MATCHED SUBPATH ' + subpath;
+        }
+    }
+    for (var subquery of configAccessMatch.subqueries) {
+        if (JSON.stringify(req.query).includes(subquery)) {
+            accessMsg += ' MATCHED SUBQUERY ' + subquery;
+        }
+    }
+    for (var text of configAccessMatch.body) {
+        if (JSON.stringify(req.body).includes(text)) {
+            accessMsg += ' MATCHED BODY ' + text;
+        }
+    }
+    return accessMsg;
+}
+
+
 /**
  * Account Log
  * read to guess its type.
@@ -190,23 +250,40 @@ function accountInfo(req, res, next) {
                 level: 'info',
                 transports: [
                     new(winston.transports.File)({
-                        filename: config.access.accountFile
+                        filename: config.access.accountFile,
+                        json: false,
+                        timestamp: false,
+                        showLevel: false
                     })
                 ]
             });
         }
         req.fwdResponse = req.fwdResponse.on('response', function(res) {
-            accessLogger.info('Right Attempt' +
-                              ' | ResponseStatus=' + req.fwdResponse.response.statusCode +
-                              ' | Token=' + req.headers['x-auth-token'] +
-                              ' | Origin=' + req.connection.remoteAddress +
-                              ' | UserId=' + req.userId +
-                              ' | ServiceId=' + req.serviceId +
-                              ' | Service=' + req.service +
-                              ' | SubServiceId=' + req.subserviceId +
-                              ' | SubService=' + req.subService +
-                              ' | Action=' + req.action +
-                              ' | Date=' + new Date().toJSON());
+            var accessMsgOrig = 'Right Attempt';
+            var accessMsg = accessMsgOrig;
+            if (! ['wrong'].includes(config.access.accountMode) ) {
+                accessMsg = checkAccessMatches(req, accessMsgOrig);
+            }
+            if ( ['all'].includes(config.access.accountMode) ||
+                 (['matched'].includes(config.access.accountMode) &&
+                  accessMsgOrig.length < accessMsg.length) ){
+
+                accessLogger.info(accessMsg +
+                                  ' | ResponseStatus=' + req.fwdResponse.response.statusCode +
+                                  ' | Token=' + req.headers['x-auth-token'] +
+                                  ' | Origin=' + (req.ip || req.connection.remoteAddress) +
+                                  ' | UserId=' + req.userId +
+                                  ' | UserName=' + req.userName +
+                                  ' | ServiceId=' + req.serviceId +
+                                  ' | Service=' + req.service +
+                                  ' | SubServiceId=' + req.subserviceId +
+                                  ' | SubService=' + req.subService +
+                                  ' | Action=' + req.action +
+                                  ' | Path=' + req.path +
+                                  ' | Query=' + JSON.stringify(req.query) +
+                                  ' | Body=' + JSON.stringify(req.body).slice(0, 100) + // not all body
+                                  ' | Date=' + new Date().toJSON());
+            }
         });
     }
     next();
@@ -257,3 +334,5 @@ exports.sendResponse = sendResponse;
 exports.accountInfo = accountInfo;
 exports.checkMandatoryHeaders = checkMandatoryHeaders(validationHeaders);
 exports.checkAuthorizationHeader = checkMandatoryHeaders(authorizationHeaders);
+exports.watchConfigAccessMatchFile = watchConfigAccessMatchFile;
+exports.checkAccessMatches = checkAccessMatches;

lib/services/keystoneAuth.js

@@ -191,6 +191,7 @@ function retrieveUser(req, callback) {
             req.serviceId = cachedValue.serviceId;
             req.domainName = cachedValue.domainName;
             req.userId = cachedValue.userId;
+            req.userName = cachedValue.userName;
 
             logger.debug('User value processed with value: %j', cachedValue);
 
@@ -245,9 +246,12 @@ function retrieveUser(req, callback) {
                     cachedValue = {
                         domainName: body.token.project.domain.name,
                         serviceId: body.token.project.domain.id,
-                        userId: body.token['OS-TRUST:trust'].trustor_user.id
+                        userId: body.token['OS-TRUST:trust'].trustor_user.id,
+                        userName: constants.NA
                     };
-
+                    if (body.token.user) {
+                        cachedValue.userName = body.token.user.name;
+                    }
                     innerCb(null, cachedValue);
 
                 } else if (body.token && body.token.user && body.token.user.domain &&
@@ -256,7 +260,8 @@ function retrieveUser(req, callback) {
                     cachedValue = {
                         domainName: body.token.user.domain.name,
                         serviceId: body.token.user.domain.id,
-                        userId: body.token.user.id
+                        userId: body.token.user.id,
+                        userName: body.token.user.name
                     };
 
                     req.userData = cachedValue;

operations.md

@@ -26,6 +26,8 @@ curl -X GET "http://localhost:11211/admin/log"
 
 Every error message is identified with a prefix code in brackets. The code convention can be found in Apendix A.
 
+There is another log about accounting access which is produced when access.account flag is enabled and is done over access.accountFile file. This accounting access logs run always in the a fixed `info` level and logs right and wrong access attempts, providing for each one user, service, subservice, path, date and other relevant info about access. Additionallys some patterns could be configured in order to mark some of these access.
+
 ## <a name="cache"/> Cache management
 
 PEP keeps a memory cache with some access about roles, domains, users and subservices. Related with this info is possible