From 0ec99cf7b46b23ea067864903865554770518d8d Mon Sep 17 00:00:00 2001 From: Anon Ray Date: Tue, 16 Jul 2019 16:00:15 +0530 Subject: [PATCH 1/5] log when request body parsing fails (fix #2555) --- server/src-lib/Hasura/Server/App.hs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/server/src-lib/Hasura/Server/App.hs b/server/src-lib/Hasura/Server/App.hs index 502c392460e1b..ca77b818b1b7b 100644 --- a/server/src-lib/Hasura/Server/App.hs +++ b/server/src-lib/Hasura/Server/App.hs @@ -252,7 +252,7 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do return (res, Nothing) AHPost handler -> do parsedReqE <- runExceptT $ parseBody reqBody - parsedReq <- either (qErrToResp (isAdmin curRole) . qErrModifier) return parsedReqE + parsedReq <- either (logAndThrow requestId req reqBody (isAdmin curRole) . qErrModifier) return parsedReqE res <- liftIO $ runReaderT (runExceptT $ handler parsedReq) handlerState return (res, Just parsedReq) @@ -269,6 +269,9 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do where logger = scLogger serverCtx + logAndThrow + :: (MonadIO m) + => RequestId -> Wai.Request -> BL.ByteString -> Bool -> QErr -> ActionCtxT ctx m b logAndThrow reqId req reqBody includeInternal qErr = do let reqTxt = Just $ toJSON $ String $ bsToTxt $ BL.toStrict reqBody logError logger Nothing reqId req reqTxt qErr From 967a14107e4e6c479a18673b2a1bb41c32b9234b Mon Sep 17 00:00:00 2001 From: Anon Ray Date: Tue, 16 Jul 2019 19:10:59 +0530 Subject: [PATCH 2/5] refactor logging code - fix a bug in websocket-log --- .../Hasura/GraphQL/Transport/WebSocket.hs | 2 +- server/src-lib/Hasura/Server/App.hs | 77 +++++++++++-------- 2 files changed, 48 insertions(+), 31 deletions(-) diff --git a/server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs b/server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs index 84b6afa56d54b..983b3c7c10410 100644 --- a/server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs +++ b/server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs @@ -136,7 +136,7 @@ data WSLogInfo , _wsliConnectionInfo :: !WsConnInfo , _wsliEvent :: !WSEvent } deriving (Show, Eq) -$(J.deriveToJSON (J.aesonDrop 4 J.snakeCase) ''WSLogInfo) +$(J.deriveToJSON (J.aesonDrop 5 J.snakeCase) ''WSLogInfo) data WSLog = WSLog diff --git a/server/src-lib/Hasura/Server/App.hs b/server/src-lib/Hasura/Server/App.hs index ca77b818b1b7b..de3fc64f5240b 100644 --- a/server/src-lib/Hasura/Server/App.hs +++ b/server/src-lib/Hasura/Server/App.hs @@ -207,9 +207,19 @@ logResult logger userInfoM reqId httpReq req res qTime = do let logline = case res of Right res' -> mkHttpAccessLog userInfoM reqId httpReq res' qTime Left e -> mkHttpErrorLog userInfoM reqId httpReq e req qTime - liftIO $ L.unLogger logger $ logline --- logResult userInfoM req reqBody logger res qTime = --- liftIO $ L.unLogger logger $ mkAccessLog userInfoM req (reqBody, res) qTime + liftIO $ L.unLogger logger logline + +logSuccess + :: (MonadIO m) + => L.Logger + -> Maybe UserInfo + -> RequestId + -> Wai.Request + -> BL.ByteString + -> Maybe (UTCTime, UTCTime) + -> m () +logSuccess logger userInfoM reqId httpReq res qTime = + liftIO $ L.unLogger logger $ mkHttpAccessLog userInfoM reqId httpReq res qTime logError :: (MonadIO m) @@ -238,7 +248,7 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do requestId <- getRequestId headers userInfoE <- liftIO $ runExceptT $ getUserInfo logger manager headers authMode - userInfo <- either (logAndThrow requestId req reqBody False . qErrModifier) + userInfo <- either (logErrorAndResp Nothing requestId req reqBody False . qErrModifier) return userInfoE let handlerState = HandlerCtx serverCtx userInfo headers requestId @@ -252,7 +262,7 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do return (res, Nothing) AHPost handler -> do parsedReqE <- runExceptT $ parseBody reqBody - parsedReq <- either (logAndThrow requestId req reqBody (isAdmin curRole) . qErrModifier) return parsedReqE + parsedReq <- either (logErrorAndResp (Just userInfo) requestId req reqBody (isAdmin curRole) . qErrModifier) return parsedReqE res <- liftIO $ runReaderT (runExceptT $ handler parsedReq) handlerState return (res, Just parsedReq) @@ -261,39 +271,46 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do -- apply the error modifier let modResult = fmapL qErrModifier result - -- log result - logResult logger (Just userInfo) requestId req (toJSON <$> q) - (apiRespToLBS <$> modResult) $ Just (t1, t2) - either (qErrToResp (isAdmin curRole)) (resToResp requestId) modResult + -- log and return result + case modResult of + Left err -> logParsedErrorAndResp (Just userInfo) requestId req (toJSON <$> q) (isAdmin curRole) err + Right res -> logSuccessAndResp (Just userInfo) requestId req res (Just (t1, t2)) + -- logResult logger (Just userInfo) requestId req (toJSON <$> q) + -- (apiRespToLBS <$> modResult) $ Just (t1, t2) + --either (qErrToResp (isAdmin curRole)) (resToResp requestId) modResult where - logger = scLogger serverCtx + logger = scLogger serverCtx - logAndThrow + logParsedErrorAndResp :: (MonadIO m) - => RequestId -> Wai.Request -> BL.ByteString -> Bool -> QErr -> ActionCtxT ctx m b - logAndThrow reqId req reqBody includeInternal qErr = do - let reqTxt = Just $ toJSON $ String $ bsToTxt $ BL.toStrict reqBody - logError logger Nothing reqId req reqTxt qErr - qErrToResp includeInternal qErr - - -- encode error response - qErrToResp :: (MonadIO m) => Bool -> QErr -> ActionCtxT ctx m b - qErrToResp includeInternal qErr = do + => Maybe UserInfo -> RequestId -> Wai.Request -> Maybe Value -> Bool -> QErr -> ActionCtxT ctx m b + logParsedErrorAndResp userInfo reqId req reqBody includeInternal qErr = do + logError logger userInfo reqId req reqBody qErr setStatus $ qeStatus qErr json $ qErrEncoder includeInternal qErr - resToResp reqId = \case - JSONResp (HttpResponse j h) -> do - uncurry setHeader jsonHeader - uncurry setHeader (requestIdHeader, unRequestId reqId) - mapM_ (mapM_ (uncurry setHeader . unHeader)) h - lazyBytes $ encJToLBS j - RawResp (HttpResponse b h) -> do - uncurry setHeader (requestIdHeader, unRequestId reqId) - mapM_ (mapM_ (uncurry setHeader . unHeader)) h - lazyBytes b + logErrorAndResp + :: (MonadIO m) + => Maybe UserInfo -> RequestId -> Wai.Request -> BL.ByteString -> Bool -> QErr -> ActionCtxT ctx m b + logErrorAndResp userInfo reqId req reqBody includeInternal qErr = do + let reqTxt = Just $ toJSON $ String $ bsToTxt $ BL.toStrict reqBody + logError logger userInfo reqId req reqTxt qErr + setStatus $ qeStatus qErr + json $ qErrEncoder includeInternal qErr + logSuccessAndResp userInfo reqId req result qTime = do + logSuccess logger userInfo reqId req (apiRespToLBS result) qTime + case result of + JSONResp (HttpResponse j h) -> do + uncurry setHeader jsonHeader + uncurry setHeader (requestIdHeader, unRequestId reqId) + mapM_ (mapM_ (uncurry setHeader . unHeader)) h + lazyBytes $ encJToLBS j + RawResp (HttpResponse b h) -> do + uncurry setHeader (requestIdHeader, unRequestId reqId) + mapM_ (mapM_ (uncurry setHeader . unHeader)) h + lazyBytes b v1QueryHandler :: RQLQuery -> Handler (HttpResponse EncJSON) v1QueryHandler query = do From 1ccfdca91c67ffd27888d3b48af23eeee5351749 Mon Sep 17 00:00:00 2001 From: Anon Ray Date: Wed, 17 Jul 2019 16:17:39 +0530 Subject: [PATCH 3/5] fix review comments - tidy logging in jwk-refresh-log - fix a minor bug in refreshing JWK: the JWK refreshed 10 seconds before the actual expiry (assuming the expiry time will always be larger than 10 seconds). Fix that. --- server/src-lib/Hasura/Server/App.hs | 24 ++++++------------ server/src-lib/Hasura/Server/Auth/JWT.hs | 15 ++++++++--- .../src-lib/Hasura/Server/Auth/JWT/Logging.hs | 25 ++++++++++++------- server/src-lib/Hasura/Server/Utils.hs | 2 +- 4 files changed, 36 insertions(+), 30 deletions(-) diff --git a/server/src-lib/Hasura/Server/App.hs b/server/src-lib/Hasura/Server/App.hs index de3fc64f5240b..8140ec587fb19 100644 --- a/server/src-lib/Hasura/Server/App.hs +++ b/server/src-lib/Hasura/Server/App.hs @@ -245,10 +245,12 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do let headers = requestHeaders req authMode = scAuthMode serverCtx manager = scManager serverCtx + -- convert ByteString to Maybe Value for logging + reqTxt = Just $ String $ bsToTxt $ BL.toStrict reqBody requestId <- getRequestId headers userInfoE <- liftIO $ runExceptT $ getUserInfo logger manager headers authMode - userInfo <- either (logErrorAndResp Nothing requestId req reqBody False . qErrModifier) + userInfo <- either (logErrorAndResp Nothing requestId req reqTxt False . qErrModifier) return userInfoE let handlerState = HandlerCtx serverCtx userInfo headers requestId @@ -262,7 +264,7 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do return (res, Nothing) AHPost handler -> do parsedReqE <- runExceptT $ parseBody reqBody - parsedReq <- either (logErrorAndResp (Just userInfo) requestId req reqBody (isAdmin curRole) . qErrModifier) return parsedReqE + parsedReq <- either (logErrorAndResp (Just userInfo) requestId req reqTxt (isAdmin curRole) . qErrModifier) return parsedReqE res <- liftIO $ runReaderT (runExceptT $ handler parsedReq) handlerState return (res, Just parsedReq) @@ -273,29 +275,17 @@ mkSpockAction qErrEncoder qErrModifier serverCtx apiHandler = do -- log and return result case modResult of - Left err -> logParsedErrorAndResp (Just userInfo) requestId req (toJSON <$> q) (isAdmin curRole) err + Left err -> logErrorAndResp (Just userInfo) requestId req (toJSON <$> q) (isAdmin curRole) err Right res -> logSuccessAndResp (Just userInfo) requestId req res (Just (t1, t2)) - -- logResult logger (Just userInfo) requestId req (toJSON <$> q) - -- (apiRespToLBS <$> modResult) $ Just (t1, t2) - --either (qErrToResp (isAdmin curRole)) (resToResp requestId) modResult where logger = scLogger serverCtx - logParsedErrorAndResp - :: (MonadIO m) - => Maybe UserInfo -> RequestId -> Wai.Request -> Maybe Value -> Bool -> QErr -> ActionCtxT ctx m b - logParsedErrorAndResp userInfo reqId req reqBody includeInternal qErr = do - logError logger userInfo reqId req reqBody qErr - setStatus $ qeStatus qErr - json $ qErrEncoder includeInternal qErr - logErrorAndResp :: (MonadIO m) - => Maybe UserInfo -> RequestId -> Wai.Request -> BL.ByteString -> Bool -> QErr -> ActionCtxT ctx m b + => Maybe UserInfo -> RequestId -> Wai.Request -> Maybe Value -> Bool -> QErr -> ActionCtxT ctx m a logErrorAndResp userInfo reqId req reqBody includeInternal qErr = do - let reqTxt = Just $ toJSON $ String $ bsToTxt $ BL.toStrict reqBody - logError logger userInfo reqId req reqTxt qErr + logError logger userInfo reqId req reqBody qErr setStatus $ qeStatus qErr json $ qErrEncoder includeInternal qErr diff --git a/server/src-lib/Hasura/Server/Auth/JWT.hs b/server/src-lib/Hasura/Server/Auth/JWT.hs index 5032a56a231f5..39b609452f2a5 100644 --- a/server/src-lib/Hasura/Server/Auth/JWT.hs +++ b/server/src-lib/Hasura/Server/Auth/JWT.hs @@ -98,6 +98,13 @@ defaultRoleClaim = "x-hasura-default-role" defaultClaimNs :: T.Text defaultClaimNs = "https://hasura.io/jwt/claims" +-- | if the time is greater than 100 seconds, should refresh the JWK 10 seonds +-- before the expiry, else refresh at given seconds +computeDiffTime :: NominalDiffTime -> Int +computeDiffTime t = + let intTime = diffTimeToMicro t + in if intTime > 100 then intTime - 10 else intTime + -- | create a background thread to refresh the JWK jwkRefreshCtrl :: (MonadIO m) @@ -113,7 +120,9 @@ jwkRefreshCtrl lggr mngr url ref time = forever $ do res <- runExceptT $ updateJwkRef lggr mngr url ref mTime <- either (const $ return Nothing) return res - C.threadDelay $ maybe (60 * aSecond) diffTimeToMicro mTime + -- if can't parse time from header, defaults to 1 min + let delay = maybe (60 * aSecond) computeDiffTime mTime + C.threadDelay delay where aSecond = 1000 * 1000 @@ -130,7 +139,7 @@ updateJwkRef updateJwkRef (Logger logger) manager url jwkRef = do let options = wreqOptions manager [] urlT = T.pack $ show url - infoMsg = "refreshing JWK from endpoint: " <> urlT + infoMsg = JLNInfo $ "refreshing JWK from endpoint: " <> urlT liftIO $ logger $ JwkRefreshLog LevelInfo infoMsg Nothing res <- liftIO $ try $ Wreq.getWith options $ show url resp <- either logAndThrowHttp return res @@ -158,7 +167,7 @@ updateJwkRef (Logger logger) manager url jwkRef = do where logAndThrow :: (MonadIO m, MonadError T.Text m) => T.Text -> Maybe JwkRefreshHttpError -> m a logAndThrow err httpErr = do - liftIO $ logger $ JwkRefreshLog (LevelOther "critical") err httpErr + liftIO $ logger $ JwkRefreshLog (LevelOther "critical") (JLNError err) httpErr throwError err logAndThrowHttp :: (MonadIO m, MonadError T.Text m) => HTTP.HttpException -> m a diff --git a/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs b/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs index b532a8487b130..162541259f084 100644 --- a/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs +++ b/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs @@ -1,7 +1,7 @@ module Hasura.Server.Auth.JWT.Logging ( JwkRefreshLog (..) , JwkRefreshHttpError (..) - , mkJwkRefreshLog + , JwkLogNotice (..) ) where @@ -17,10 +17,15 @@ import qualified Data.Text as T import qualified Network.HTTP.Types as HTTP +data JwkLogNotice + = JLNInfo !Text + | JLNError !Text + deriving (Show) + data JwkRefreshLog = JwkRefreshLog { jrlLogLevel :: !LogLevel - , jrlError :: !T.Text + , jrlNotice :: !JwkLogNotice , jrlHttpError :: !(Maybe JwkRefreshHttpError) } deriving (Show) @@ -41,14 +46,16 @@ instance ToJSON JwkRefreshHttpError where ] instance ToJSON JwkRefreshLog where - toJSON jrl = - object [ "error" .= jrlError jrl - , "http_error" .= (toJSON <$> jrlHttpError jrl) - ] + toJSON jrl = case jrlNotice jrl of + JLNInfo info -> + object [ "message" .= info + , "http_error" .= (toJSON <$> jrlHttpError jrl) + ] + JLNError err -> + object [ "error" .= err + , "http_error" .= (toJSON <$> jrlHttpError jrl) + ] instance ToEngineLog JwkRefreshLog where toEngineLog jwkRefreshLog = (jrlLogLevel jwkRefreshLog, ELTJwkRefreshLog, toJSON jwkRefreshLog) - -mkJwkRefreshLog :: LogLevel -> T.Text -> Maybe JwkRefreshHttpError -> JwkRefreshLog -mkJwkRefreshLog = JwkRefreshLog diff --git a/server/src-lib/Hasura/Server/Utils.hs b/server/src-lib/Hasura/Server/Utils.hs index 90c562f086ecb..391325d81680c 100644 --- a/server/src-lib/Hasura/Server/Utils.hs +++ b/server/src-lib/Hasura/Server/Utils.hs @@ -180,7 +180,7 @@ fmapL _ (Right x) = pure x -- diff time to micro seconds diffTimeToMicro :: NominalDiffTime -> Int diffTimeToMicro diff = - (floor (realToFrac diff :: Double) - 10) * aSecond + floor (realToFrac diff :: Double) * aSecond where aSecond = 1000 * 1000 From b9812a143fa1a85df92743228aa01493641f57f6 Mon Sep 17 00:00:00 2001 From: Anon Ray Date: Wed, 17 Jul 2019 17:19:37 +0530 Subject: [PATCH 4/5] cleaner exception message on http exception in jwk-refresh-log --- server/src-lib/Hasura/Server/Auth/JWT.hs | 13 +++++++++---- server/src-lib/Hasura/Server/Auth/JWT/Logging.hs | 3 ++- 2 files changed, 11 insertions(+), 5 deletions(-) diff --git a/server/src-lib/Hasura/Server/Auth/JWT.hs b/server/src-lib/Hasura/Server/Auth/JWT.hs index 39b609452f2a5..490bbb1cd7ce0 100644 --- a/server/src-lib/Hasura/Server/Auth/JWT.hs +++ b/server/src-lib/Hasura/Server/Auth/JWT.hs @@ -165,18 +165,23 @@ updateJwkRef (Logger logger) manager url jwkRef = do return $ diffUTCTime expires currTime where - logAndThrow :: (MonadIO m, MonadError T.Text m) => T.Text -> Maybe JwkRefreshHttpError -> m a + logAndThrow + :: (MonadIO m, MonadError T.Text m) + => T.Text -> Maybe JwkRefreshHttpError -> m a logAndThrow err httpErr = do liftIO $ logger $ JwkRefreshLog (LevelOther "critical") (JLNError err) httpErr throwError err logAndThrowHttp :: (MonadIO m, MonadError T.Text m) => HTTP.HttpException -> m a logAndThrowHttp err = do - let httpErr = JwkRefreshHttpError Nothing (T.pack $ show url) - (Just $ HttpException err) Nothing - errMsg = "Error fetching JWK: " <> T.pack (show err) + let httpErr = JwkRefreshHttpError Nothing (T.pack $ show url) (Just $ HttpException err) Nothing + errMsg = "Error fetching JWK: " <> T.pack (getHttpExceptionMsg err) logAndThrow errMsg (Just httpErr) + getHttpExceptionMsg = \case + HTTP.HttpExceptionRequest _ reason -> show reason + HTTP.InvalidUrlException _ reason -> show reason + timeFmt = "%a, %d %b %Y %T GMT" diff --git a/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs b/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs index 162541259f084..6892b228f64ed 100644 --- a/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs +++ b/server/src-lib/Hasura/Server/Auth/JWT/Logging.hs @@ -12,6 +12,7 @@ import Hasura.Logging (EngineLogType (..), LogLevel (..), ToEngineLog (..)) import Hasura.Prelude import Hasura.Server.Logging () +import Hasura.Server.Utils (httpExceptToJSON) import qualified Data.Text as T import qualified Network.HTTP.Types as HTTP @@ -42,7 +43,7 @@ instance ToJSON JwkRefreshHttpError where object [ "status_code" .= (HTTP.statusCode <$> jrheStatus jhe) , "url" .= jrheUrl jhe , "response" .= jrheResponse jhe - , "http_exception" .= (toJSON <$> jrheHttpException jhe) + , "http_exception" .= (httpExceptToJSON . unHttpException <$> jrheHttpException jhe) ] instance ToJSON JwkRefreshLog where From b224985c13e2f82eb0c4047a37cbc8f90ec5b220 Mon Sep 17 00:00:00 2001 From: Anon Ray Date: Thu, 1 Aug 2019 14:57:27 +0530 Subject: [PATCH 5/5] add tests for request parsing failed logs --- server/tests-py/test_logging.py | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/server/tests-py/test_logging.py b/server/tests-py/test_logging.py index 43f5fb790cf76..0af46eebb6d80 100644 --- a/server/tests-py/test_logging.py +++ b/server/tests-py/test_logging.py @@ -21,6 +21,8 @@ def transact(self, hge_ctx): # setup some tables st_code, resp = hge_ctx.v1q_f(self.dir + '/setup.yaml') assert st_code == 200, resp + + # make a successful query q = {'query': 'query { hello {code name} }'} headers = {} if hge_ctx.hge_key: @@ -28,6 +30,17 @@ def transact(self, hge_ctx): resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, headers=headers) assert resp.status_code == 200 and 'data' in resp.json() + + # make a query where JSON body parsing fails + q = {'quer': 'query { hello {code name} }'} + headers = {'x-request-id': 'json-parse-fail-log-test'} + if hge_ctx.hge_key: + headers['x-hasura-admin-secret'] = hge_ctx.hge_key + resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, + headers=headers) + assert resp.status_code == 200 and 'errors' in resp.json() + + # gather and parse the logs now self.logs = self._parse_logs(hge_ctx) # sometimes the log might take time to buffer time.sleep(2) @@ -115,3 +128,15 @@ def _get_query_logs(x): assert 'query' in onelog assert 'query' in onelog['query'] assert 'generated_sql' in onelog + + def test_http_parse_failed_log(self, hge_ctx): + def _get_parse_failed_logs(x): + return x['type'] == 'http-log' and \ + x['detail']['operation']['request_id'] == 'json-parse-fail-log-test' + + http_logs = list(filter(_get_parse_failed_logs, self.logs)) + print('parse failed logs', http_logs) + assert len(http_logs) > 0 + print(http_logs[0]) + assert 'error' in http_logs[0]['detail']['operation'] + assert http_logs[0]['detail']['operation']['error']['code'] == 'parse-failed'