server: fix regression in query-log generation

Co-authored-by: Anon Ray <616387+ecthiender@users.noreply.github.com> GitOrigin-RevId: 74cc6bad2274dc1587f4d3b38e444857d079a4ac
2024-11-10 10:29:12 +03:00 · 2021-04-28 23:08:05 +05:30 · 2021-04-28 23:08:05 +05:30 · c834629afb
commit c834629afb
parent aca8964fdc
8 changed files with 87 additions and 64 deletions
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@ -80,7 +80,7 @@ In the future, we will probably offer a way to explicitly choose which behaviour
 - server: re-enable a default HASURA_GRAPHQL_PG_CONN_LIFETIME of 10min
 - server: support for bigquery datasets
 - server: format the values of `injectEventContext` as hexadecimal string instead of integer (fix #6465)
- server: add "kind" field to query-log items. Kind can be "database", "action", "remote-schema", "graphql", "cached", or "subscription".
+- server: add "kind" field to query-log items. Kind can be "database", "action", "remote-schema", "cached" or "introspection".
 - console: add custom_column_names to track_table request with replaced invalid characters (#992)
 - console: add details button to the success notification to see inserted row
 - console: add request preview for REST endpoints
--- a/docs/graphql/core/deployment/logging.rst
+++ b/docs/graphql/core/deployment/logging.rst
@ -54,8 +54,9 @@ All the log-types that can be enabled/disabled are:

   * - ``query-log``
     - Logs: the entire GraphQL query with variables, generated SQL statements
-       (only for queries, not for mutations/subscriptions or remote schema
-       queries), the operation name (if provided in the GraphQL request)
+       (only for database queries, not for mutations/subscriptions or remote
+       schema and action queries), the operation name (if provided in the
+       GraphQL request)
     - ``info``

   * - ``http-log``
@ -145,6 +146,7 @@ subscriptions).
      "level": "info",
      "type": "query-log",
      "detail": {
+        "kind": "database",
        "request_id": "840f952d-c489-4d21-a87a-cc23ad17926a",
        "query": {
          "variables": {
@ -172,6 +174,9 @@ under the ``detail`` key.

 This log contains 3 important fields:

+- ``kind``: indicates the type or kind of operation. ``kind`` can be
+  ``database``, ``action``, ``remote-schema``, ``cached`` or ``introspection``
+
 - ``request_id``: A unique ID for each request. If the client sends a
  ``x-request-id`` header then that is respected, otherwise a UUID is generated
  for each request. This is useful to correlate between ``http-log`` and
@ -206,7 +211,7 @@ This is how the HTTP access logs look like:
          },
          "error": null,
          "request_id": "072b3617-6653-4fd5-b5ee-580e9d098c3d",
-          "parameterized_query_hash": "7116865cef017c3b09e5c9271b0e182a6dcf4c01"
+          "parameterized_query_hash": "7116865cef017c3b09e5c9271b0e182a6dcf4c01",
          "response_size": 105,
          "query": null
        },
--- a/server/src-lib/Hasura/Backends/BigQuery/Instances/Transport.hs
+++ b/server/src-lib/Hasura/Backends/BigQuery/Instances/Transport.hs
@ -8,10 +8,11 @@ import           Hasura.Backends.MSSQL.Instances.Execute    ()
 import           Hasura.EncJSON
 import           Hasura.GraphQL.Logging                     (GeneratedQuery (..),
                                                             MonadQueryLog (..), QueryLog (..),
-                                                             QueryLogKind (Database))
+                                                             QueryLogKind (QueryLogKindDatabase))
 import           Hasura.GraphQL.Transport.Backend
 import           Hasura.GraphQL.Transport.HTTP.Protocol
 import qualified Hasura.Logging                             as L
+
 import           Hasura.Prelude
 import           Hasura.RQL.Types
 import           Hasura.Server.Types                        (RequestId)
@ -79,6 +80,6 @@ mkQueryLog
  -> RequestId
  -> QueryLog
 mkQueryLog gqlQuery fieldName preparedSql requestId =
-  QueryLog gqlQuery ((fieldName,) <$> generatedQuery) requestId Database
+  QueryLog gqlQuery ((fieldName,) <$> generatedQuery) requestId QueryLogKindDatabase
  where
    generatedQuery = preparedSql <&> \qs -> GeneratedQuery qs J.Null
--- a/server/src-lib/Hasura/Backends/MSSQL/Instances/Transport.hs
+++ b/server/src-lib/Hasura/Backends/MSSQL/Instances/Transport.hs
@ -134,6 +134,6 @@ mkQueryLog
  -> RequestId
  -> QueryLog
 mkQueryLog gqlQuery fieldName preparedSql requestId =
-  QueryLog gqlQuery ((fieldName,) <$> generatedQuery) requestId Database
+  QueryLog gqlQuery ((fieldName,) <$> generatedQuery) requestId QueryLogKindDatabase
  where
    generatedQuery = preparedSql <&> \qs -> GeneratedQuery qs J.Null
--- a/server/src-lib/Hasura/Backends/Postgres/Instances/Transport.hs
+++ b/server/src-lib/Hasura/Backends/Postgres/Instances/Transport.hs
@ -126,7 +126,7 @@ mkQueryLog
  -> RequestId
  -> QueryLog
 mkQueryLog gqlQuery fieldName preparedSql requestId =
-  QueryLog gqlQuery ((fieldName,) <$> generatedQuery) requestId Database
+  QueryLog gqlQuery ((fieldName,) <$> generatedQuery) requestId QueryLogKindDatabase
  where
    generatedQuery = preparedSql <&> \(EQ.PreparedSql query args _) ->
      GeneratedQuery (Q.getQueryText query) (J.toJSON $ pgScalarValueToJson . snd <$> args)
--- a/server/src-lib/Hasura/GraphQL/Logging.hs
+++ b/server/src-lib/Hasura/GraphQL/Logging.hs
@ -13,6 +13,7 @@ module Hasura.GraphQL.Logging
 import           Hasura.Prelude

 import qualified Data.Aeson                             as J
+import qualified Data.HashMap.Strict                    as Map
 import qualified Language.GraphQL.Draft.Syntax          as G

 import qualified Hasura.Logging                         as L
@ -33,21 +34,19 @@ data QueryLog = QueryLog
  }

 data QueryLogKind
-  = Database
-  | Action
-  | RemoteSchema
-  | GraphQL
-  | Cached
-  | Subscription -- This field is a workaround due to src-lib/Hasura/GraphQL/Transport/WebSocket.hs logging the query before execution is determined.
+  = QueryLogKindDatabase
+  | QueryLogKindAction
+  | QueryLogKindRemoteSchema
+  | QueryLogKindCached
+  | QueryLogKindIntrospection

 instance J.ToJSON QueryLogKind where
  toJSON = \case
-    Database     -> "database"
-    Action       -> "action"
-    RemoteSchema -> "remote-schema"
-    GraphQL      -> "graphql"
-    Cached       -> "cached"
-    Subscription -> "subscription"
+    QueryLogKindDatabase      -> "database"
+    QueryLogKindAction        -> "action"
+    QueryLogKindRemoteSchema  -> "remote-schema"
+    QueryLogKindCached        -> "cached"
+    QueryLogKindIntrospection -> "introspection"

 data GeneratedQuery = GeneratedQuery
  { _gqQueryString  :: Text
@ -57,10 +56,13 @@ data GeneratedQuery = GeneratedQuery
 instance J.ToJSON QueryLog where
  toJSON (QueryLog gqlQuery generatedQuery reqId kind) =
    J.object [ "query"         J..= gqlQuery
-             , "generated_sql" J..= generatedQuery
+             -- NOTE: this customizes the default JSON instance of a pair
+             , "generated_sql" J..= fmap fromPair generatedQuery
             , "request_id"    J..= reqId
             , "kind"          J..= kind
             ]
+    where
+      fromPair p = Map.fromList [first G.unName p]

 instance J.ToJSON GeneratedQuery where
  toJSON (GeneratedQuery queryString preparedArgs) =
--- a/server/src-lib/Hasura/GraphQL/Transport/HTTP.hs
+++ b/server/src-lib/Hasura/GraphQL/Transport/HTTP.hs
@ -50,7 +50,7 @@ import           Hasura.Backends.Postgres.Instances.Transport (runPGMutationTran
 import           Hasura.EncJSON
 import           Hasura.GraphQL.Context
 import           Hasura.GraphQL.Logging                       (MonadQueryLog (logQueryLog),
-                                                               QueryLog (..), QueryLogKind (Cached))
+                                                               QueryLog (..), QueryLogKind (..))
 import           Hasura.GraphQL.Parser.Column                 (UnpreparedValue (..))
 import           Hasura.GraphQL.Parser.Schema                 (Variable)
 import           Hasura.GraphQL.Transport.Backend
@ -233,7 +233,7 @@ runGQ env logger reqId userInfo ipAddress reqHeaders queryType reqUnparsed = do
        (responseHeaders, cachedValue) <- Tracing.interpTraceT (liftEitherM . runExceptT) $ cacheLookup remoteJoins actionsInfo cacheKey
        case fmap decodeGQResp cachedValue of
          Just cachedResponseData -> do
-            logQueryLog logger $ QueryLog reqUnparsed Nothing reqId Cached
+            logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindCached
            pure (Telem.Query, 0, Telem.Local, HttpResponse cachedResponseData responseHeaders, normalizedSelectionSet)

          Nothing -> do
@ -252,12 +252,15 @@ runGQ env logger reqId userInfo ipAddress reqHeaders queryType reqUnparsed = do
                          tx
                          genSql
                return $ ResultsFragment telemTimeIO_DT Telem.Local resp []
-              E.ExecStepRemote rsi gqlReq ->
+              E.ExecStepRemote rsi gqlReq -> do
+                logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindRemoteSchema
                runRemoteGQ httpManager fieldName rsi gqlReq
              E.ExecStepAction (aep, _) -> do
+                logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindAction
                (time, (r, _)) <- doQErr $ EA.runActionExecution aep
                pure $ ResultsFragment time Telem.Empty r []
-              E.ExecStepRaw json ->
+              E.ExecStepRaw json -> do
+                logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindIntrospection
                buildRaw json
            out@(_, _, _, HttpResponse responseData _, _) <-
              buildResultFromFragments Telem.Query conclusion responseHeaders normalizedSelectionSet
@ -306,12 +309,15 @@ runGQ env logger reqId userInfo ipAddress reqHeaders queryType reqUnparsed = do
                          tx
                          genSql
                return $ ResultsFragment telemTimeIO_DT Telem.Local resp responseHeaders
-              E.ExecStepRemote rsi gqlReq ->
+              E.ExecStepRemote rsi gqlReq -> do
+                logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindRemoteSchema
                runRemoteGQ httpManager fieldName rsi gqlReq
              E.ExecStepAction (aep, _) -> do
+                logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindAction
                (time, (r, hdrs)) <- doQErr $ EA.runActionExecution aep
                pure $ ResultsFragment time Telem.Empty r $ fromMaybe [] hdrs
-              E.ExecStepRaw json ->
+              E.ExecStepRaw json -> do
+                logQueryLog logger $ QueryLog reqUnparsed Nothing reqId QueryLogKindIntrospection
                buildRaw json
            buildResultFromFragments Telem.Mutation conclusion [] normalizedSelectionSet

--- a/server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs
+++ b/server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs
@ -383,7 +383,7 @@ onStart env serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do
            E.ExecStepDB _remoteHeaders exists ->
              AB.dispatchAnyBackend @BackendTransport exists EB.getRemoteSchemaInfo
            _ -> []
-          actionsInfo = foldl getExecStepActionWithActionInfo [] $ OMap.elems $ OMap.filter (\x -> case x of
+          actionsInfo = foldl getExecStepActionWithActionInfo [] $ OMap.elems $ OMap.filter (\case
              E.ExecStepAction (_, _) -> True
              _                       -> False
              ) queryPlan
@ -393,6 +393,7 @@ onStart env serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do
      (_responseHeaders, cachedValue) <- Tracing.interpTraceT (withExceptT mempty) $ cacheLookup remoteJoins actionsInfo cacheKey
      case cachedValue of
        Just cachedResponseData -> do
+          logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindCached
          sendSuccResp cachedResponseData $ LQ.LiveQueryMetadata 0
        Nothing -> do
          conclusion <- runExceptT $ forWithKey queryPlan $ \fieldName -> \case
@ -411,11 +412,14 @@ onStart env serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do
                       genSql
              return $ ResultsFragment telemTimeIO_DT Telem.Local resp []
            E.ExecStepRemote rsi gqlReq -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindRemoteSchema
              runRemoteGQ fieldName userInfo reqHdrs rsi gqlReq
            E.ExecStepAction (actionExecPlan, _) -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindAction
              (time, (r, _)) <- doQErr $ EA.runActionExecution actionExecPlan
              pure $ ResultsFragment time Telem.Empty r []
-            E.ExecStepRaw json ->
+            E.ExecStepRaw json -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindIntrospection
              buildRaw json
          buildResultFromFragments Telem.Query telemCacheHit timerTot requestId conclusion
          case conclusion of
@ -462,43 +466,45 @@ onStart env serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do
                         genSql
              return $ ResultsFragment telemTimeIO_DT Telem.Local resp []
            E.ExecStepAction (actionExecPlan, _) -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindAction
              (time, (r, hdrs)) <- doQErr $ EA.runActionExecution actionExecPlan
              pure $ ResultsFragment time Telem.Empty r $ fromMaybe [] hdrs
            E.ExecStepRemote rsi gqlReq -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindRemoteSchema
              runRemoteGQ fieldName userInfo reqHdrs rsi gqlReq
-            E.ExecStepRaw json ->
+            E.ExecStepRaw json -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindIntrospection
              buildRaw json
          buildResultFromFragments Telem.Query telemCacheHit timerTot requestId conclusion
      liftIO $ sendCompleted (Just requestId)

    E.SubscriptionExecutionPlan subExec -> do
-      -- log the graphql query
-      logQueryLog logger $ QueryLog q Nothing requestId Subscription
-
      case subExec of
-        E.SEAsyncActionsWithNoRelationships actions -> liftIO do
-          let allActionIds = map fst $ OMap.elems actions
-          case NE.nonEmpty allActionIds of
-            Nothing -> sendCompleted $ Just requestId
-            Just actionIds -> do
-              let sendResponseIO actionLogMap = do
-                   (dTime, resultsE) <- withElapsedTime $ runExceptT $
-                     for actions $ \(actionId, resultBuilder) -> do
-                       actionLogResponse <- Map.lookup actionId actionLogMap
-                         `onNothing` throw500 "unexpected: cannot lookup action_id in response map"
-                       liftEither $ resultBuilder actionLogResponse
-                   case resultsE of
-                     Left err -> sendError requestId err
-                     Right results -> do
-                       let dataMsg = SMData $ DataMsg opId $ pure $ encJToLBS $
-                                     encJFromInsOrdHashMap $ OMap.mapKeys G.unName results
-                       sendMsgWithMetadata wsConn dataMsg $ LQ.LiveQueryMetadata dTime
+        E.SEAsyncActionsWithNoRelationships actions -> do
+          logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindAction
+          liftIO do
+            let allActionIds = map fst $ OMap.elems actions
+            case NE.nonEmpty allActionIds of
+              Nothing -> sendCompleted $ Just requestId
+              Just actionIds -> do
+                let sendResponseIO actionLogMap = do
+                     (dTime, resultsE) <- withElapsedTime $ runExceptT $
+                       for actions $ \(actionId, resultBuilder) -> do
+                         actionLogResponse <- Map.lookup actionId actionLogMap
+                           `onNothing` throw500 "unexpected: cannot lookup action_id in response map"
+                         liftEither $ resultBuilder actionLogResponse
+                     case resultsE of
+                       Left err -> sendError requestId err
+                       Right results -> do
+                         let dataMsg = SMData $ DataMsg opId $ pure $ encJToLBS $
+                                       encJFromInsOrdHashMap $ OMap.mapKeys G.unName results
+                         sendMsgWithMetadata wsConn dataMsg $ LQ.LiveQueryMetadata dTime

-                  asyncActionQueryLive = LQ.LAAQNoRelationships $
-                    LQ.LiveAsyncActionQueryWithNoRelationships sendResponseIO (sendCompleted (Just requestId))
+                    asyncActionQueryLive = LQ.LAAQNoRelationships $
+                      LQ.LiveAsyncActionQueryWithNoRelationships sendResponseIO (sendCompleted (Just requestId))

-              LQ.addAsyncActionLiveQuery (LQ._lqsAsyncActions lqMap) opId actionIds
-                                         (sendError requestId) asyncActionQueryLive
+                LQ.addAsyncActionLiveQuery (LQ._lqsAsyncActions lqMap) opId actionIds
+                                           (sendError requestId) asyncActionQueryLive

        E.SEOnSourceDB actionIds liveQueryBuilder -> do
          actionLogMapE <- fmap fst <$> runExceptT (EA.fetchActionLogResponses actionIds)
@ -508,20 +514,23 @@ onStart env serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do

          -- Update async action query subscription state
          case NE.nonEmpty (toList actionIds) of
-            Nothing                ->
+            Nothing                -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindDatabase
              -- No async action query fields present, do nothing.
              pure ()
-            Just nonEmptyActionIds -> liftIO $ do
-              let asyncActionQueryLive = LQ.LAAQOnSourceDB $
-                    LQ.LiveAsyncActionQueryOnSource lqId actionLogMap $ restartLiveQuery liveQueryBuilder
+            Just nonEmptyActionIds -> do
+              logQueryLog logger $ QueryLog q Nothing requestId QueryLogKindAction
+              liftIO $ do
+                let asyncActionQueryLive = LQ.LAAQOnSourceDB $
+                      LQ.LiveAsyncActionQueryOnSource lqId actionLogMap $ restartLiveQuery liveQueryBuilder

-                  onUnexpectedException err = do
-                    sendError requestId err
-                    stopOperation serverEnv wsConn opId (pure ()) -- Don't log in case opId don't exist
+                    onUnexpectedException err = do
+                      sendError requestId err
+                      stopOperation serverEnv wsConn opId (pure ()) -- Don't log in case opId don't exist

-              LQ.addAsyncActionLiveQuery (LQ._lqsAsyncActions lqMap) opId
-                                          nonEmptyActionIds onUnexpectedException
-                                          asyncActionQueryLive
+                LQ.addAsyncActionLiveQuery (LQ._lqsAsyncActions lqMap) opId
+                                            nonEmptyActionIds onUnexpectedException
+                                            asyncActionQueryLive

      liftIO $ logOpEv ODStarted (Just requestId)
  where