Added request ID logging to trace individual requests (#28)

* Added request ID logging to trace individual requests * Fixed tests
rorylshanks · Mar 17, 2024 · 91b5444 · 91b5444
1 parent 644c3e9
commit 91b5444
Show file tree

Hide file tree

Showing 11 changed files with 101 additions and 57 deletions.
diff --git a/lib/authz.js b/lib/authz.js
@@ -11,13 +11,14 @@ async function authZRequest(req, res, route) {
     var userId = req.session.userId
     var user = await idp.getUserById(userId)
     if (!user) {
-        log.info({ "action": "userDoesNotExistInIdp", "user": userId, context: { url: requestUrl } })
+        log.infoWithContext(req, { "action": "userDoesNotExistInIdp", "user": userId, context: { url: requestUrl } })
         return false
     }
     var allowedGroups = route.allowed_groups
 
     var discoveredGroups = await checkUserGroupMembership(user, allowedGroups)
     if (discoveredGroups.length >= 1) {
+        log.infoWithContext(req, { discoveredGroups })
         log.access("userIsAllowedBasedOnGroupMembership", route, user, req)
         await addRequestedHeaders(req, res, route, user, discoveredGroups)
         return "OK - Groups"

diff --git a/lib/dynamic-backend.js b/lib/dynamic-backend.js
@@ -14,7 +14,7 @@ async function checkDynamicBackend(req, res, route, requestUrl) {
         const responseBody = response.data
         const proxyUrl = responseBody.url
         const responseHeaders = responseBody.headers
-        log.info({ "action": "dynamicBackendSessionOk", "url": responseBody });
+        log.infoWithContext(req, { "action": "dynamicBackendSessionOk", "url": responseBody });
         for (let header of responseHeaders) {
             res.set(header.key, header.value)
         }

diff --git a/lib/http.js b/lib/http.js
@@ -3,18 +3,17 @@ const app = express();
 import session from 'express-session';
 import ssoController from './sso.js';
 
-
 import redisHelper from "../util/redis.js"
 import log from '../util/logging.js'
 import { getConfig, getRedirectBasepath, getAuthListenPort } from '../util/config.js';
 import { pem2jwk } from 'pem-jwk';
 import crypto from 'crypto';
 import errorpages from '../util/errorpage.js'
 import metrics from '../util/metrics.js'
-
+import { randomUUID } from 'node:crypto'
 
 var trusted_ranges = ["loopback"].concat(getConfig().trusted_ranges || [])
-log.info({ message: `Setting trusted proxies to ${trusted_ranges}` })
+log.debug({ message: `Setting trusted proxies to ${trusted_ranges}` })
 app.set('trust proxy', trusted_ranges)
 
 var defaultCookieOptions = { maxAge: 3600000 }
@@ -58,6 +57,16 @@ generateJwks()
 app.use(express.json());
 app.use(express.urlencoded({ extended: true }))
 
+// Request ID setting middleware
+app.use((req, res, next) => {
+  var requestId = req.get("x-veriflow-request-id")
+  if (!requestId) {
+    requestId = randomUUID()
+  }
+  req.headers["X-Veriflow-Request-Id"] = requestId
+  next()
+})
+
 var redirectBasePath = getRedirectBasepath()
 
 app.get('/ping', (req, res) => {
@@ -71,7 +80,7 @@ app.get(redirectBasePath + '/logout', async (req, res) => {
   if (req.session.loggedin) {
     await redisHelper.logUserOutAllSessions(req.session.userId)
   }
-  var html = await errorpages.renderErrorPage(200, "LOGOUT_SUCCESS")
+  var html = await errorpages.renderErrorPage(200, "LOGOUT_SUCCESS", req)
   res.send(html)
 })
 

diff --git a/lib/token-auth.js b/lib/token-auth.js
@@ -65,14 +65,14 @@ async function checkAuthHeader(req, res, route) {
     }
     var token = await getConfigFromToken(headerValue, route)
     if (!token) {
-        log.info({ message: "User tried to use invalid token", context: { token: headerValue, route } })
+        log.infoWithContext(req, { message: "User tried to use invalid token", context: { token: headerValue, route } })
         return null
     }
     var domainIsAllowed = pm.isMatch((route.from.url || route.from), token.valid_domains) || pm.isMatch((route.to.url || route.to), token.valid_domains)
     if (domainIsAllowed) {
         return token
     } else {
-        log.info({ message: "User tried to use token for invalid domain", context: { user: token.userId, route } })
+        log.infoWithContext(req, { message: "User tried to use token for invalid domain", context: { user: token.userId, route } })
         return null
     }
 }

diff --git a/test/e2e/tests/basic_test.js b/test/e2e/tests/basic_test.js
@@ -60,15 +60,15 @@ Scenario('Testing Token Auth', async ({ I }) => {
 Scenario('Testing Unauthorized Flow', async ({ I }) => {
     I.amOnPage('http://test-unauthorized-login.localtest.me/');
     I.login()
-    I.see("ERR_NOT_AUTHORIZED")
+    I.see("Unauthorized")
 });
 
 Scenario('Advanced matchers test', async ({ I }) => {
     I.amOnPage('http://test-advanced-matchers.localtest.me/get');
     I.login();
     I.see("x-veriflow-user-id")
     I.amOnPage('http://test-advanced-matchers.localtest.me/should404');
-    I.see("ERR_ROUTE_NOT_FOUND")
+    I.see("Page Not Found")
 });
 
 Scenario('Dynamic Upstreams Test', async ({ I }) => {

diff --git a/util/caddyModels.js b/util/caddyModels.js
@@ -130,8 +130,8 @@ async function saturateRoute(route, routeId) {
     "Host": [
       route.preserve_host_header ? "{http.request.host}" : "{http.reverse_proxy.upstream.host}"
     ],
-    "X-Veriflow-Request": [
-      "true"
+    "X-Veriflow-Request-Id": [
+      "{http.request.uuid}"
     ]
   }
   if (route.set_request_headers) {
@@ -233,6 +233,9 @@ async function saturateRoute(route, routeId) {
                       ],
                       "X-Veriflow-Route-Id": [
                         routeId
+                      ],
+                      "X-Veriflow-Request-Id": [
+                        "{http.request.uuid}"
                       ]
                     }
                   }
@@ -303,43 +306,60 @@ async function generateCaddyConfig() {
   var config = getConfig()
   var routes = await saturateAllRoutesFromConfig(config)
 
-  const E_LOOP_DETECTED_HTML = await errorpage.renderErrorPage(503, "ERR_LOOP_DETECTED")
-  const E_NOT_FOUND_HTML = await errorpage.renderErrorPage(404, "ERR_ROUTE_NOT_FOUND")
-
-  var circuitBreakerRoute = {
+  var requestIdRoute = {
     "handle": [
       {
-        "handler": "subroute",
-        "routes": [
-          {
-            "handle": [
-              {
-                "body": E_LOOP_DETECTED_HTML,
-                "close": true,
-                "handler": "static_response",
-                "status_code": 503,
-                "headers": {
-                  "Content-Type": [
-                    "text/html"
-                  ]
-                }
-              }
+        "handler": "headers",
+        "response": {
+          "set": {
+            "X-Veriflow-Request-Id": [
+              "{http.request.uuid}"
             ]
           }
-        ]
-      }
-    ],
-    "match": [
-      {
-        "header": {
-          "X-Veriflow-Request": [
-            "true"
-          ]
         }
       }
     ]
   }
-  routes.unshift(circuitBreakerRoute)
+  routes.unshift(requestIdRoute)
+
+  if (config.enable_circuit_breaker_route !== false) {
+    log.debug("Enabling circuit breaker route")
+    const E_LOOP_DETECTED_HTML = await errorpage.renderErrorPage(503, "ERR_LOOP_DETECTED")
+    var circuitBreakerRoute = {
+      "handle": [
+        {
+          "handler": "subroute",
+          "routes": [
+            {
+              "handle": [
+                {
+                  "body": E_LOOP_DETECTED_HTML,
+                  "close": true,
+                  "handler": "static_response",
+                  "status_code": 503,
+                  "headers": {
+                    "Content-Type": [
+                      "text/html"
+                    ]
+                  }
+                }
+              ]
+            }
+          ]
+        }
+      ],
+      "match": [
+        {
+          "header": {
+            "X-Veriflow-Request-Id": [
+            ]
+          }
+        }
+      ]
+    }
+    routes.unshift(circuitBreakerRoute)
+  }
+
 
   var serviceUrl = new URL(config.service_url)
   var serviceRoute = {
@@ -371,6 +391,8 @@ async function generateCaddyConfig() {
     ],
     "terminal": true
   }
+
+  const E_NOT_FOUND_HTML = await errorpage.renderErrorPage(404, "ERR_ROUTE_NOT_FOUND")
   var defaultRoute = {
     "handle": [
       {

diff --git a/util/config.js b/util/config.js
@@ -76,7 +76,7 @@ function getAuthListenPort() {
             authListenPort++
         } else {
             foundPort = authListenPort
-            log.info({ message: `Found port ${foundPort} for the auth service to listen on`})
+            log.debug({ message: `Found port ${foundPort} for the auth service to listen on`})
         }
     }
     return foundPort

diff --git a/util/errorpage.js b/util/errorpage.js
@@ -22,7 +22,7 @@ async function renderErrorPage(status_code, error_code_override, req) {
     var logo_image_src = config?.ui?.logo_image_src || false
     var page_title = config?.ui?.page_title || "Veriflow"
 
-    var description = "An internal server error occoured. Please try again."
+    var description = "An internal server error occurred. Please try again."
     var error_code = "ERR_INTERNAL_ERROR"
     if (status_code == 404) {
         header = "Page Not Found"
@@ -31,7 +31,7 @@ async function renderErrorPage(status_code, error_code_override, req) {
     }
     if (status_code == 403) {
         header = "Unauthorized"
-        description = "You are not authorized to acces the requested resource."
+        description = "You are not authorized to access the requested resource."
         error_code = "ERR_NOT_AUTHORIZED"
     }
     if (status_code == 503) {
@@ -62,7 +62,8 @@ async function renderErrorPage(status_code, error_code_override, req) {
         background_image_url: background_image_url,
         additional_css: additional_css,
         show_error_code: show_error_code,
-        logo_image_src: logo_image_src
+        logo_image_src: logo_image_src,
+        request_id: req?.headers["X-Veriflow-Request-Id"] || "{http.request.uuid}"
     });
     return html
 }

diff --git a/util/logging.js b/util/logging.js
@@ -2,9 +2,10 @@ import pino from 'pino';
 
 const log = pino();
 
-log.level = 10
+log.level = 30
 
 log.access = (action, route, user, req) => {
+    let reqId = req.headers["X-Veriflow-Request-Id"]
     let method = req.get("X-Forwarded-Method")
     let path = req.get("X-Forwarded-Path")
     let query = req.get("X-Forwarded-Query")
@@ -18,6 +19,7 @@ log.access = (action, route, user, req) => {
         userInfo.mail = user.mail
     }
     log.info({
+        reqId,
         action: action,
         request: {
             method,
@@ -37,4 +39,11 @@ log.access = (action, route, user, req) => {
 
 }
 
+log.infoWithContext = (req, message) => {
+    log.info({
+        reqId: req.headers["X-Veriflow-Request-Id"], 
+        ...message
+    })
+}
+
 export default log;
diff --git a/views/error_fullpage.ejs b/views/error_fullpage.ejs
@@ -9,28 +9,29 @@
     <div class="container">
         <div class="header">
             <div class="logo"><%- include('includes/logo'); %></div>
-            <% if(user){ %>
+
             <div class="menu">
                 <div class="hamburger-menu" onclick="toggleMenu()">☰</div>
                 <div class="menu-content" id="menu">
-                    <a>Logged in as <%= user %></a>
-                    <a href="<%= logout_url %>">Logout</a>
+                    <% if(show_error_code){ %>
+                        <a>Status Code: <%= error_code %></a>
+                    <% } %>
+                        <a>Request ID: <%= request_id %></a>
+
+                    <% if(user){ %>
+                        <a>Logged in as <%= user %></a>
+                        <hr>
+                        <a href="<%= logout_url %>">Logout of Veriflow</a>
+                    <% }%> 
                 </div>
             </div>
-            <% }%> 
+
         </div>
         <div class="content">
             <h1><%= header %></h1>
             <hr>
             <p class="error-message"><%= description %></p>
         </div>
-        <div class="footer">
-            <% if(show_error_code){ %>
-                <div><%= error_code %></div>
-             <% } %>
-
-        </div>
-
     </div>
 </body>
 <footer>

diff --git a/views/includes/style.ejs b/views/includes/style.ejs
@@ -45,6 +45,7 @@
         }
 
         .menu-content {
+            text-align: left;
             display: none;
             right: 0;
             position: absolute;