server: add query field to http-log and websocket-log

https://github.com/hasura/graphql-engine-mono/pull/1683

GitOrigin-RevId: 6f46e31bb14f135d528b20ae9513e393c06c3c8a

CHANGELOG.md

@@ -3,6 +3,7 @@
 ## Next release
 (Add entries below in the order of server, console, cli, docs, others)
 
+- server: add `query` field to `http-log` and `websocket-log` in non-error cases
 - server: Add global limit to BigQuery via the `global_select_limit`
   field in the connection configuration
 

server/src-lib/Hasura/App.hs

@@ -841,9 +841,9 @@ instance (MonadIO m) => HttpLog (PGMetadataStorageAppT m) where
     unLogger logger $ mkHttpLog $
       mkHttpErrorLogContext userInfoM reqId waiReq req qErr Nothing Nothing headers
 
-  logHttpSuccess logger userInfoM reqId waiReq _reqBody _response compressedResponse qTime cType headers () =
+  logHttpSuccess logger userInfoM reqId waiReq reqBody _response compressedResponse qTime cType headers () =
     unLogger logger $ mkHttpLog $
-      mkHttpAccessLogContext userInfoM reqId waiReq compressedResponse qTime cType headers
+      mkHttpAccessLogContext userInfoM reqId waiReq reqBody compressedResponse qTime cType headers
 
 instance (Monad m) => MonadExecuteQuery (PGMetadataStorageAppT m) where
   cacheLookup _ _ _ _ = pure ([], Nothing)

server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs

@@ -611,11 +611,7 @@ onStart env serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do
     WSConnData userInfoR opMap errRespTy queryType = WS.getData wsConn
 
     logOpEv opTy reqId = logWSEvent logger wsConn $ EOperation $
-      OperationDetails opId reqId (_grOperationName q) opTy $
-      -- log the query only in errors
-      case opTy of
-        ODQueryErr _ -> Just q
-        _            -> Nothing
+      OperationDetails opId reqId (_grOperationName q) opTy (Just q)
 
     getErrFn ERTLegacy           = encodeQErr
     getErrFn ERTGraphqlCompliant = encodeGQLErr

server/src-lib/Hasura/Server/App.hs

@@ -360,7 +360,7 @@ mkSpockAction serverCtx qErrEncoder qErrModifier apiHandler = do
         AHGet handler -> do
           (userInfo, handlerState, includeInternal) <- getInfo Nothing
           res <- lift $ runHandler handlerState handler
-          return (res , userInfo, includeInternal, Nothing)
+          return (res, userInfo, includeInternal, Nothing)
         AHPost handler -> do
           (userInfo, handlerState, includeInternal) <- getInfo Nothing
           parsedReqE <- runExceptT $ parseBody reqBody
@@ -418,7 +418,7 @@ mkSpockAction serverCtx qErrEncoder qErrModifier apiHandler = do
             allRespHeaders = pure reqIdHeader <> encodingHeader <> respHeaders
         lift $ logHttpSuccess logger userInfo reqId waiReq
                req respBytes compressedResp qTime mCompressionType reqHeaders httpLoggingMetadata
-        mapM_ setHeader allRespHeaders
+        traverse_ setHeader allRespHeaders
         Spock.lazyBytes compressedResp
 
 v1QueryHandler

server/src-lib/Hasura/Server/Logging.hs

@@ -257,12 +257,13 @@ mkHttpAccessLogContext
   -- ^ Maybe because it may not have been resolved
   -> RequestId
   -> Wai.Request
+  -> (BL.ByteString, Maybe Value)
   -> BL.ByteString
   -> Maybe (DiffTime, DiffTime)
   -> Maybe CompressionType
   -> [HTTP.Header]
   -> HttpLogContext
-mkHttpAccessLogContext userInfoM reqId req res mTiming compressTypeM headers =
+mkHttpAccessLogContext userInfoM reqId req (_, parsedReq) res mTiming compressTypeM headers =
   let http = HttpInfoLog
              { hlStatus      = status
              , hlMethod      = bsToTxt $ Wai.requestMethod req
@@ -278,7 +279,7 @@ mkHttpAccessLogContext userInfoM reqId req res mTiming compressTypeM headers =
            , olResponseSize = respSize
            , olRequestReadTime    = Seconds . fst <$> mTiming
            , olQueryExecutionTime = Seconds . snd <$> mTiming
-           , olQuery = Nothing
+           , olQuery = parsedReq
            , olRawQuery = Nothing
            , olError = Nothing
            }
@@ -315,6 +316,7 @@ mkHttpErrorLogContext userInfoM reqId waiReq (reqBody, parsedReq) err mTiming co
            , olRequestReadTime    = Seconds . fst <$> mTiming
            , olQueryExecutionTime = Seconds . snd <$> mTiming
            , olQuery              = parsedReq
+           -- if parsedReq is Nothing, add the raw query
            , olRawQuery           = maybe (Just $ bsToTxt $ BL.toStrict reqBody) (const Nothing) parsedReq
            , olError              = Just err
            }

server/tests-py/test_logging.py

@@ -12,6 +12,7 @@ if not PytestConf.config.getoption("--test-logging"):
 
 class TestLogging():
     dir = 'queries/logging'
+    success_query = {'query': 'query { hello {code name} }'}
 
     def _teardown(self, hge_ctx):
         st_code, resp = hge_ctx.v1q_f(self.dir + '/teardown.yaml')
@@ -25,7 +26,7 @@ class TestLogging():
 
         try:
             # make a successful query
-            q = {'query': 'query { hello {code name} }'}
+            q = self.success_query
             headers = {'x-request-id': 'successful-query-log-test'}
             if hge_ctx.hge_key:
                 headers['x-hasura-admin-secret'] = hge_ctx.hge_key
@@ -147,6 +148,11 @@ class TestLogging():
             if operation['request_id'] == 'successful-query-log-test':
                 assert 'query_execution_time' in operation
                 assert 'user_vars' in operation
+                # we should see the `query` field in successful operations
+                assert 'query' in operation
+                assert operation['query'] == self.success_query
+                # there shouldn't be any raw_query in success
+                assert operation.get('raw_query') is None
 
     def test_query_log(self, hge_ctx):
         def _get_query_logs(x):