fix(condo): INFRA-296 logging pipeline adjustments (#4756)

* fix(keystone): INFRA-296 add log for every incoming request * fix(keystone): INFRA-296 move gql response log output to the last callback of apollo lifecycle * fix(global): INFRA-296 completely disable auto-logging * fix(global): INFRA-296 pass request id from ingress to app & add test logs for debug * fix(condo): INFRA-296 try to pass nginx req_id to the app * fix(condo): INFRA-296 try to pass nginx req_id to the app * fix(condo): INFRA-296 try to pass nginx req_id to the app * fix(global): INFRA-296 try to get req.id from ingress headers * fix(global): INFRA-296 try to increase ephemeral-storage for pg review * fix(global): INFRA-296 try to increase ephemeral-storage for pg review * fix(global): INFRA-296 try to get req.id from ingress headers * fix(global): INFRA-296 try to get req.id from ingress headers * fix(global): INFRA-296 try to get req.id from ingress headers * fix(global): INFRA-296 try to get req.id from ingress headers * fix(global): INFRA-296 remove test logs * fix(global): INFRA-296 restore original app side reqId passing scenario * fix(global): INFRA-296 provide more info at gql operation timings * fix(global): INFRA-296 add initial log for gql request was received by app * fix(global): INFRA-296 update all ingresses * fix(global): INFRA-296 update helm submodule to master * refactor(keystone): INFRA-296 use native rounding & rename time calculaiton function
open-condo-software · Jun 7, 2024 · 7964913 · 7964913
1 parent 8a8d499
commit 7964913
Show file tree

Hide file tree

Showing 4 changed files with 34 additions and 26 deletions.
diff --git a/.helm b/.helm
diff --git a/packages/keystone/KSv5v6/v5/prepareKeystone.js b/packages/keystone/KSv5v6/v5/prepareKeystone.js
@@ -17,8 +17,7 @@ const { parseCorsSettings } = require('@open-condo/keystone/cors.utils')
 const { _internalGetExecutionContextAsyncLocalStorage } = require('@open-condo/keystone/executionContext')
 const { IpBlackListMiddleware } = require('@open-condo/keystone/ipBlackList')
 const { registerSchemas } = require('@open-condo/keystone/KSv5v6/v5/registerSchema')
-const { getLogger } = require('@open-condo/keystone/logging')
-const { getKeystonePinoOptions, GraphQLLoggerPlugin } = require('@open-condo/keystone/logging')
+const { getKeystonePinoOptions, GraphQLLoggerPlugin, getLogger } = require('@open-condo/keystone/logging')
 const { expressErrorHandler } = require('@open-condo/keystone/logging/expressErrorHandler')
 const metrics = require('@open-condo/keystone/metrics')
 const { schemaDocPreprocessor, adminDocPreprocessor, escapeSearchPreprocessor, customAccessPostProcessor } = require('@open-condo/keystone/preprocessors')

diff --git a/packages/keystone/logging/GraphQLLoggerApp.js b/packages/keystone/logging/GraphQLLoggerApp.js
@@ -39,32 +39,45 @@ function renderExecutableDefinitionNode (node) {
     return ''
 }
 
+/**
+ * Get current time in nanoseconds and return diff between
+ * @param time {bigint} start time of the operation
+ * @returns {number} Operation elapsed time in milliseconds
+ */
+function timeFrom (time) {
+    const diff = process.hrtime.bigint() - time
+
+    return +(Number(diff) / 1000000).toFixed(4)
+}
+
 /**
  * @type {import('apollo-server-plugin-base').ApolloServerPlugin}
  */
 class GraphQLLoggerPlugin {
-    /**
-     * @param { import('apollo-server-types').GraphQLRequestContext } requestContext
-     * @returns {Promise<void>}
-     */
     requestDidStart (requestContext) {
-        const startTime = process.hrtime.bigint()
+        let timeUntilExecution = null
+        const requestStartTime = process.hrtime.bigint()
+        graphqlLogger.info({
+            state: 'requestDidStart',
+            ...getGraphQLReqLoggerContext(requestContext),
+        })
 
         return {
-            /**
-             * The responseForOperation event is fired immediately before GraphQL execution would take place.
-             * If its return value resolves to a non-null GraphQLResponse, that result is used instead of executing the query.
-             * Hooks from different plugins are invoked in series, and the first non-null response is used.
-             * @param {import('apollo-server-types').WithRequired<import('apollo-server-types').GraphQLRequestContext<TContext>, 'metrics' | 'source' | 'document' | 'operationName' | 'operation' | 'logger'>} requestContext
-             * @returns {Promise<import('apollo-server-types').GraphQLResponse | null>}
-             */
             async responseForOperation (requestContext) {
                 const operationId = get(requestContext, 'operationId') || cuid()
                 // NOTE(pahaz): log correlation id for cases where not reqId
                 requestContext.operationId = operationId
-
-                const logData = getGraphQLReqLoggerContext(requestContext)
-                graphqlLogger.info({ ...logData, responseTime: Number(process.hrtime.bigint() - startTime) / 1000000 })
+            },
+            async executionDidStart () {
+                timeUntilExecution = timeFrom(requestStartTime)
+            },
+            async willSendResponse (requestContext) {
+                graphqlLogger.info({
+                    ...getGraphQLReqLoggerContext(requestContext),
+                    responseTime: timeFrom(requestStartTime),
+                    timeUntilExecution,
+                    state: 'willSendResponse',
+                })
             },
 
             /**
@@ -74,17 +87,16 @@ class GraphQLLoggerPlugin {
             async didEncounterErrors (requestContext) {
                 const logData = getGraphQLReqLoggerContext(requestContext)
                 const errors = get(requestContext, 'errors', [])
-                const responseTime = Number(process.hrtime.bigint() - startTime) / 1000000
 
                 try {
                     for (const error of errors) {
                         error.uid = get(error, 'uid') || get(error, 'originalError.uid') || cuid()
-                        graphqlErrorLogger.info({ apolloFormatError: safeFormatError(error), ...logData, responseTime })
+                        graphqlErrorLogger.info({ apolloFormatError: safeFormatError(error), ...logData })
                     }
                 } catch (formatErrorError) {
                     // NOTE(pahaz): Something went wrong with formatting above, so we log the errors
-                    graphqlErrorLogger.error({ formatErrorError: serializeError(ensureError(formatErrorError)), ...logData, responseTime })
-                    graphqlErrorLogger.error({ serializedErrors: errors.map(error => serializeError(ensureError(error))), ...logData, responseTime })
+                    graphqlErrorLogger.error({ formatErrorError: serializeError(ensureError(formatErrorError)), ...logData })
+                    graphqlErrorLogger.error({ serializedErrors: errors.map(error => serializeError(ensureError(error))), ...logData })
                 }
             },
         }

diff --git a/packages/keystone/logging/getKeystonePinoOptions.js b/packages/keystone/logging/getKeystonePinoOptions.js
@@ -2,15 +2,12 @@ const { getLogger } = require('./getLogger')
 const { getReqLoggerContext } = require('./getReqLoggerContext')
 
 const logger = getLogger('http')
-const IGNORE_PATH = new Set(['/api/features', '/api/version', '/favicon.ico'])
 
 function getKeystonePinoOptions () {
     // NOTE(pahaz): https://github.com/pinojs/pino-http#pinohttpopts-stream
     return {
         logger,
-        autoLogging: {
-            ignore: (req) => IGNORE_PATH.has(req.url),
-        },
+        autoLogging: false,
         customProps: (req, res) => {
             return getReqLoggerContext(req)
         },