fix(condo):INFRA-296 logging pipeline adjustments

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')

packages/keystone/logging/GraphQLLoggerApp.js

@@ -39,32 +39,50 @@ 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 endTimer (time) {
+    function roundTo (decimalPlaces, numberToRound) {
+        const factorOfTen = Math.pow(10, decimalPlaces)
+        return +(Math.round(numberToRound * factorOfTen)  / factorOfTen)
+    }
+    const diff = process.hrtime.bigint() - time
+    const elapsed = Number(diff) / 1000000
+
+    return roundTo(4, elapsed)
+}
+
 /**
  * @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 = endTimer(requestStartTime)
+            },
+            async willSendResponse (requestContext) {
+                graphqlLogger.info({
+                    ...getGraphQLReqLoggerContext(requestContext),
+                    responseTime: endTimer(requestStartTime),
+                    timeUntilExecution,
+                    state: 'willSendResponse',
+                })
             },
 
             /**
@@ -74,17 +92,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 })
                 }
             },
         }

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)
         },