hasura/graphql-engine
1
0
Fork 0
mirror of https://github.com/hasura/graphql-engine.git synced 2024-09-11 10:46:25 +03:00
Code Issues Projects Releases Wiki Activity

http and websocket logs now correctly have user information, closes #849 (#850)

Browse Source
This commit is contained in:
Vamshi Surabhi 2018-10-25 15:07:57 +05:30 committed by GitHub
parent 1266bbf354
commit 199531cbd9
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
12 changed files with 93 additions and 102 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
docs/graphql/manual/deployment/docker/logging.rst
View File

@ -13,8 +13,8 @@ GraphQL engine container:
$ docker logs cdfbc6b94c70
{"timestamp":"2018-10-09T11:20:32.054+0000", "level":"info", "type":"http-log", "detail":{"status":200, "query_hash":"01640c6dd131826cff44308111ed40d7fbd1cbed", "http_version":"HTTP/1.1", "query_execution_time":3.0177627e-2, "request_id":null, "url":"/v1alpha1/graphql", "hasura_metadata":null, "ip":"127.0.0.1", "response_size":209329, "method":"POST", "hasura_role":null, "detail":null}}
{"timestamp":"2018-10-09T11:20:32.054+0000", "level":"info", "type":"http-log", "detail":{"status":200, "query_hash":"01640c6dd131826cff44308111ed40d7fbd1cbed", "http_version":"HTTP/1.1", "query_execution_time":3.0177627e-2, "request_id":null, "url":"/v1alpha1/graphql", "user":{"x-hasura-role":"admin"}, "ip":"127.0.0.1", "response_size":209329, "method":"POST", "detail":null}}
...
See https://docs.docker.com/config/containers/logging for more details on logging in Docker.
See https://docs.docker.com/config/containers/logging for more details on logging in Docker.

4
docs/graphql/manual/deployment/heroku/logging.rst
View File

@ -8,7 +8,7 @@ of Hasura GraphQL engine deployed on Heroku:
$ heroku logs --app <hasura-graphql-engine-app-name>
2018-10-09T11:18:21.306000+00:00 app[web.1]: {"timestamp":"2018-10-09T11:18:21.305+0000", "level":"info", "type":"http-log", "detail":{"status":200, "query_hash":"48c74f902b53a886f9ddc1b7dd12a4a6020d70c3", "http_version":"HTTP/1.1", "query_execution_time":9.477913e-3, "request_id":"b7bb6fb3-97b3-4c6f-a54a-1e0f71a190e9", "url":"/v1alpha1/graphql", "hasura_metadata":null, "ip":"171.61.77.16", "response_size":15290, "method":"POST", "hasura_role":null, "detail":null}}
2018-10-09T11:18:21.306000+00:00 app[web.1]: {"timestamp":"2018-10-09T11:18:21.305+0000", "level":"info", "type":"http-log", "detail":{"status":200, "query_hash":"48c74f902b53a886f9ddc1b7dd12a4a6020d70c3", "http_version":"HTTP/1.1", "query_execution_time":9.477913e-3, "request_id":"b7bb6fb3-97b3-4c6f-a54a-1e0f71a190e9", "url":"/v1alpha1/graphql", "user":{"x-hasura-role":"admin"}, "ip":"171.61.77.16", "response_size":15290, "method":"POST", "detail":null}}
...
See https://devcenter.heroku.com/articles/logging for more details on logging in Heroku.
See https://devcenter.heroku.com/articles/logging for more details on logging in Heroku.

4
docs/graphql/manual/deployment/kubernetes/logging.rst
View File

@ -8,8 +8,8 @@ service, i.e. ``hasura``:
$ kubectl logs -f svc/hasura
{"timestamp":"2018-10-09T11:20:32.054+0000", "level":"info", "type":"http-log", "detail":{"status":200, "query_hash":"01640c6dd131826cff44308111ed40d7fbd1cbed", "http_version":"HTTP/1.1", "query_execution_time":3.0177627e-2, "request_id":null, "url":"/v1alpha1/graphql", "hasura_metadata":null, "ip":"127.0.0.1", "response_size":209329, "method":"POST", "hasura_role":null, "detail":null}}
{"timestamp":"2018-10-09T11:20:32.054+0000", "level":"info", "type":"http-log", "detail":{"status":200, "query_hash":"01640c6dd131826cff44308111ed40d7fbd1cbed", "http_version":"HTTP/1.1", "query_execution_time":3.0177627e-2, "request_id":null, "url":"/v1alpha1/graphql", "user":{"x-hasura-role":"admin"}, "ip":"127.0.0.1", "response_size":209329, "method":"POST", "detail":null}}
...
See https://kubernetes.io/docs/concepts/cluster-administration/logging for more details on logging in Kubernetes.
See https://kubernetes.io/docs/concepts/cluster-administration/logging for more details on logging in Kubernetes.

2
server/src-lib/Hasura/GraphQL/Explain.hs
View File

@ -97,7 +97,7 @@ explainField userInfo gCtx fld =
"lookup failed: opctx: " <> showName f
validateHdrs hdrs = do
let receivedHdrs = userHeaders userInfo
let receivedHdrs = userVars userInfo
forM_ hdrs $ \hdr ->
unless (Map.member hdr receivedHdrs) $
throw400 NotFound $ hdr <<> " header is expected but not found"

2
server/src-lib/Hasura/GraphQL/Resolve.hs
View File

@ -60,7 +60,7 @@ buildTx userInfo gCtx fld = do
"lookup failed: opctx: " <> showName f
validateHdrs hdrs = do
let receivedHdrs = userHeaders userInfo
let receivedHdrs = userVars userInfo
forM_ hdrs $ \hdr ->
unless (Map.member hdr receivedHdrs) $
throw400 NotFound $ hdr <<> " header is expected but not found"

39
server/src-lib/Hasura/GraphQL/Transport/WebSocket.hs
View File

@ -98,6 +98,7 @@ $(J.deriveToJSON
data WSLog
= WSLog
{ _wslWebsocketId :: !WS.WSId
, _wslUser :: !(Maybe UserVars)
, _wslEvent :: !WSEvent
} deriving (Show, Eq)
$(J.deriveToJSON (J.aesonDrop 4 J.snakeCase) ''WSLog)
@ -127,14 +128,14 @@ onConn (L.Logger logger) wsId requestHead = do
threadDelay $ 5 * 1000 * 1000
accept _ = do
logger $ WSLog wsId EAccepted
logger $ WSLog wsId Nothing EAccepted
connData <- WSConnData <$> IORef.newIORef Nothing <*> STMMap.newIO
let acceptRequest = WS.defaultAcceptRequest
{ WS.acceptSubprotocol = Just "graphql-ws"}
return $ Right (connData, acceptRequest, Just keepAliveAction)
reject qErr = do
logger $ WSLog wsId $ ERejected qErr
logger $ WSLog wsId Nothing $ ERejected qErr
return $ Left $ WS.RejectRequest
(H.statusCode $ qeStatus qErr)
(H.statusMessage $ qeStatus qErr) []
@ -185,13 +186,12 @@ onStart serverEnv wsConn (StartMsg opId q) = catchAndIgnore $ do
sendCompleted
where
WSServerEnv (L.Logger logger) _ runTx lqMap gCtxMapRef _ = serverEnv
WSServerEnv logger _ runTx lqMap gCtxMapRef _ = serverEnv
wsId = WS.getWSId wsConn
WSConnData userInfoR opMap = WS.getData wsConn
logOpEv opDet =
liftIO $ logger $ WSLog wsId $
EOperation opId (_grOperationName q) opDet
logWSEvent logger wsConn $ EOperation opId (_grOperationName q) opDet
sendConnErr connErr = do
sendMsg wsConn $ SMErr $ ErrorMsg opId $ J.toJSON connErr
@ -235,7 +235,7 @@ onMessage authMode serverEnv wsConn msgRaw =
case J.eitherDecode msgRaw of
Left e -> do
let err = ConnErrMsg $ "parsing ClientMessage failed: " <> T.pack e
liftIO $ logger $ WSLog (WS.getWSId wsConn) $ EConnErr err
logWSEvent logger wsConn $ EConnErr err
sendMsg wsConn $ SMConnErr err
Right msg -> case msg of
@ -246,7 +246,7 @@ onMessage authMode serverEnv wsConn msgRaw =
CMStop stopMsg -> onStop serverEnv wsConn stopMsg
CMConnTerm -> WS.closeConn wsConn "GQL_CONNECTION_TERMINATE received"
where
logger = L.unLogger $ _wseLogger serverEnv
logger = _wseLogger serverEnv
onStop :: WSServerEnv -> WSConn -> StopMsg -> IO ()
onStop serverEnv wsConn (StopMsg opId) = do
@ -255,27 +255,40 @@ onStop serverEnv wsConn (StopMsg opId) = do
case opM of
Just liveQ -> do
let opNameM = _grOperationName $ LQ._lqRequest liveQ
liftIO $ logger $ WSLog wsId $ EOperation opId opNameM ODStopped
logWSEvent logger wsConn $ EOperation opId opNameM ODStopped
LQ.removeLiveQuery lqMap liveQ (wsId, opId)
Nothing -> return ()
STM.atomically $ STMMap.delete opId opMap
where
logger = L.unLogger $ _wseLogger serverEnv
logger = _wseLogger serverEnv
lqMap = _wseLiveQMap serverEnv
wsId = WS.getWSId wsConn
opMap = _wscOpMap $ WS.getData wsConn
logWSEvent
:: (MonadIO m)
=> L.Logger -> WSConn -> WSEvent -> m ()
logWSEvent (L.Logger logger) wsConn wsEv = do
userInfoME <- liftIO $ IORef.readIORef userInfoR
let userInfoM = case userInfoME of
Just (Right userInfo) -> return $ userVars userInfo
_ -> Nothing
liftIO $ logger $ WSLog wsId userInfoM wsEv
where
WSConnData userInfoR _ = WS.getData wsConn
wsId = WS.getWSId wsConn
onConnInit
:: (MonadIO m)
=> L.Logger -> H.Manager -> WSConn -> AuthMode -> Maybe ConnParams -> m ()
onConnInit (L.Logger logger) manager wsConn authMode connParamsM = do
onConnInit logger manager wsConn authMode connParamsM = do
res <- runExceptT $ getUserInfo logger manager headers authMode
case res of
Left e -> do
liftIO $ IORef.writeIORef (_wscUser $ WS.getData wsConn) $
Just $ Left $ qeError e
let connErr = ConnErrMsg $ qeError e
liftIO $ logger $ WSLog (WS.getWSId wsConn) $ EConnErr connErr
logWSEvent logger wsConn $ EConnErr connErr
sendMsg wsConn $ SMConnErr connErr
Right userInfo -> do
liftIO $ IORef.writeIORef (_wscUser $ WS.getData wsConn) $
@ -295,8 +308,8 @@ onClose
-> WS.ConnectionException
-> WSConn
-> IO ()
onClose (L.Logger logger) lqMap _ wsConn = do
logger $ WSLog wsId EClosed
onClose logger lqMap _ wsConn = do
logWSEvent logger wsConn EClosed
operations <- STM.atomically $ ListT.toList $ STMMap.stream opMap
void $ A.forConcurrently operations $ \(opId, liveQ) ->
LQ.removeLiveQuery lqMap liveQ (wsId, opId)

2
server/src-lib/Hasura/RQL/DML/Internal.hs
View File

@ -243,7 +243,7 @@ toJSONableExp colTy expn
-- validate headers
validateHeaders :: (P1C m) => [T.Text] -> m ()
validateHeaders depHeaders = do
headers <- M.keys . userHeaders <$> askUserInfo
headers <- M.keys . userVars <$> askUserInfo
forM_ depHeaders $ \hdr ->
unless (hdr `elem` map T.toLower headers) $
throw400 NotFound $ hdr <<> " header is expected but not found"

7
server/src-lib/Hasura/RQL/Types/Permission.hs
View File

@ -8,6 +8,7 @@
module Hasura.RQL.Types.Permission
( RoleName(..)
, UserId(..)
, UserVars
, UserInfo(..)
, adminUserInfo
, adminRole
@ -52,10 +53,12 @@ isAdmin = (adminRole ==)
newtype UserId = UserId { getUserId :: Word64 }
deriving (Show, Eq, FromJSON, ToJSON)
type UserVars = (Map.HashMap T.Text T.Text)
data UserInfo
= UserInfo
{ userRole :: !RoleName
, userHeaders :: !(Map.HashMap T.Text T.Text)
{ userRole :: !RoleName
, userVars :: !UserVars
} deriving (Show, Eq, Generic)
instance Hashable UserInfo

20
server/src-lib/Hasura/Server/App.hs
View File

@ -124,18 +124,20 @@ buildQCtx = do
logResult
:: (MonadIO m)
=> Wai.Request -> BL.ByteString -> ServerCtx
=> Maybe UserInfo -> Wai.Request -> BL.ByteString -> ServerCtx
-> Either QErr BL.ByteString -> Maybe (UTCTime, UTCTime)
-> m ()
logResult req reqBody sc res qTime =
liftIO $ logger $ mkAccessLog req (reqBody, res) qTime
logResult userInfoM req reqBody sc res qTime =
liftIO $ logger $ mkAccessLog userInfoM req (reqBody, res) qTime
where
logger = L.unLogger $ scLogger sc
logError
:: MonadIO m
=> Wai.Request -> BL.ByteString -> ServerCtx -> QErr -> m ()
logError req reqBody sc qErr = logResult req reqBody sc (Left qErr) Nothing
=> Maybe UserInfo -> Wai.Request
-> BL.ByteString -> ServerCtx -> QErr -> m ()
logError userInfoM req reqBody sc qErr =
logResult userInfoM req reqBody sc (Left qErr) Nothing
mkSpockAction
:: (MonadIO m)
@ -160,18 +162,18 @@ mkSpockAction qErrEncoder serverCtx handler = do
t2 <- liftIO getCurrentTime -- for measuring response time purposes
-- log result
logResult req reqBody serverCtx result $ Just (t1, t2)
logResult (Just userInfo) req reqBody serverCtx result $ Just (t1, t2)
either (qErrToResp $ userRole userInfo == adminRole) resToResp result
where
logger = L.unLogger $ scLogger serverCtx
logger = scLogger serverCtx
-- encode error response
qErrToResp includeInternal qErr = do
setStatus $ qeStatus qErr
json $ qErrEncoder includeInternal qErr
logAndThrow req reqBody includeInternal qErr = do
logError req reqBody serverCtx qErr
logError Nothing req reqBody serverCtx qErr
qErrToResp includeInternal qErr
resToResp resp = do
@ -338,7 +340,7 @@ httpApp mRootDir corsCfg serverCtx enableConsole = do
let qErr = err404 NotFound "resource does not exist"
req <- request
reqBody <- liftIO $ strictRequestBody req
logError req reqBody serverCtx qErr
logError Nothing req reqBody serverCtx qErr
uncurry setHeader jsonHeader
lazyBytes $ encode qErr

11
server/src-lib/Hasura/Server/Auth.hs
View File

@ -60,7 +60,7 @@ data AuthMode
mkUserInfoFromResp
:: (MonadIO m, MonadError QErr m)
=> WebHookLogger
=> L.Logger
-> T.Text
-> N.Status
-> BL.ByteString
@ -95,12 +95,12 @@ mkUserInfoFromResp logger url statusCode respBody
logWebHookResp L.LevelError $ Just respBody
logWebHookResp logLevel mResp =
liftIO $ logger $ WebHookLog logLevel (Just statusCode)
liftIO $ L.unLogger logger $ WebHookLog logLevel (Just statusCode)
url Nothing $ fmap (bsToTxt . BL.toStrict) mResp
userInfoFromWebhook
:: (MonadIO m, MonadError QErr m)
=> WebHookLogger
=> L.Logger
-> H.Manager
-> Webhook
-> [N.Header]
@ -122,7 +122,8 @@ userInfoFromWebhook logger manager hook reqHeaders = do
where
logAndThrow err = do
let urlT = getWebhook hook
liftIO $ logger $ WebHookLog L.LevelError Nothing urlT (Just err) Nothing
liftIO $ L.unLogger logger $
WebHookLog L.LevelError Nothing urlT (Just err) Nothing
throw500 "Internal Server Error"
filteredHeaders = flip filter reqHeaders $ \(n, _) ->
@ -135,7 +136,7 @@ userInfoFromWebhook logger manager hook reqHeaders = do
getUserInfo
:: (MonadIO m, MonadError QErr m)
=> WebHookLogger
=> L.Logger
-> H.Manager
-> [N.Header]
-> AuthMode

98
server/src-lib/Hasura/Server/Logging.hs
View File

@ -11,33 +11,32 @@ module Hasura.Server.Logging
, WebHookLogger
) where
import Control.Arrow (first)
import Crypto.Hash (Digest, SHA1, hash)
import Crypto.Hash (Digest, SHA1, hash)
import Data.Aeson
import Data.Bits (shift, (.&.))
import Data.ByteString.Char8 (ByteString)
import qualified Data.ByteString.Lazy as BL
import Data.Int (Int64)
import Data.List (find)
import qualified Data.TByteString as TBS
import qualified Data.Text as T
import qualified Data.Text.Encoding as TE
import Data.Bits (shift, (.&.))
import Data.ByteString.Char8 (ByteString)
import qualified Data.ByteString.Lazy as BL
import Data.Int (Int64)
import Data.List (find)
import qualified Data.TByteString as TBS
import qualified Data.Text as T
import qualified Data.Text.Encoding as TE
import Data.Time.Clock
import Data.Word (Word32)
import Network.Socket (SockAddr (..))
import Network.Wai (Request (..))
import System.ByteOrder (ByteOrder (..), byteOrder)
import Text.Printf (printf)
import Data.Word (Word32)
import Network.Socket (SockAddr (..))
import Network.Wai (Request (..))
import System.ByteOrder (ByteOrder (..), byteOrder)
import Text.Printf (printf)
import qualified Data.ByteString.Char8 as BS
import qualified Data.CaseInsensitive as CI
import qualified Data.HashMap.Strict as M
import qualified Network.HTTP.Client as H
import qualified Network.HTTP.Types as N
import qualified Data.ByteString.Char8 as BS
import qualified Data.CaseInsensitive as CI
import qualified Network.HTTP.Client as H
import qualified Network.HTTP.Types as N
import qualified Hasura.Logging as L
import qualified Hasura.Logging as L
import Hasura.Prelude
import Hasura.RQL.Types.Error
import Hasura.RQL.Types.Permission
import Hasura.Server.Utils
@ -82,8 +81,7 @@ data AccessLog
, alHttpVersion :: !N.HttpVersion
, alDetail :: !(Maybe Value)
, alRequestId :: !(Maybe T.Text)
, alHasuraRole :: !(Maybe T.Text)
, alHasuraMetadata :: !(Maybe Value)
, alHasuraUser :: !(Maybe UserVars)
, alQueryHash :: !(Maybe T.Text)
, alResponseSize :: !(Maybe Int64)
, alResponseTime :: !(Maybe Double)
@ -94,7 +92,7 @@ instance L.ToEngineLog AccessLog where
(L.LevelInfo, "http-log", toJSON accessLog)
instance ToJSON AccessLog where
toJSON (AccessLog st met src path hv det reqId hRole hMd qh rs rt) =
toJSON (AccessLog st met src path hv det reqId hUser qh rs rt) =
object [ "status" .= N.statusCode st
, "method" .= met
, "ip" .= src
@ -102,8 +100,7 @@ instance ToJSON AccessLog where
, "http_version" .= show hv
, "detail" .= det
, "request_id" .= reqId
, "hasura_role" .= hRole
, "hasura_metadata" .= hMd
, "user" .= hUser
, "query_hash" .= qh
, "response_size" .= rs
, "query_execution_time" .= rt
@ -159,24 +156,24 @@ ravenLogGen (reqBody, res) =
sha1 = hash . BL.toStrict
mkAccessLog
:: Request
:: Maybe UserInfo -- may not have been resolved
-> Request
-> (BL.ByteString, Either QErr BL.ByteString)
-> Maybe (UTCTime, UTCTime)
-> AccessLog
mkAccessLog req r mTimeT =
mkAccessLog userInfoM req r mTimeT =
AccessLog
{ alStatus = status
, alMethod = bsToTxt $ requestMethod req
, alSource = bsToTxt $ getSourceFromFallback req
, alPath = bsToTxt $ rawPathInfo req
, alHttpVersion = httpVersion req
, alDetail = mDetail
, alRequestId = bsToTxt <$> getRequestId req
, alHasuraRole = bsToTxt <$> getHasuraRole req
, alHasuraMetadata = getHasuraMetadata req
{ alStatus = status
, alMethod = bsToTxt $ requestMethod req
, alSource = bsToTxt $ getSourceFromFallback req
, alPath = bsToTxt $ rawPathInfo req
, alHttpVersion = httpVersion req
, alDetail = mDetail
, alRequestId = bsToTxt <$> getRequestId req
, alHasuraUser = userVars <$> userInfoM
, alResponseSize = size
, alResponseTime = realToFrac <$> diffTime
, alQueryHash = queryHash
, alQueryHash = queryHash
}
where
(status, mDetail, queryHash, size) = ravenLogGen r
@ -203,37 +200,12 @@ requestIdHeader = "x-request-id"
getRequestId :: Request -> Maybe ByteString
getRequestId = getRequestHeader $ TE.encodeUtf8 requestIdHeader
getHasuraRole :: Request -> Maybe ByteString
getHasuraRole = getRequestHeader $ TE.encodeUtf8 userRoleHeader
getRequestHeader :: ByteString -> Request -> Maybe ByteString
getRequestHeader hdrName req = snd <$> mHeader
where
mHeader = find (\h -> fst h == CI.mk hdrName) hdrs
hdrs = requestHeaders req
newtype HasuraMetadata
= HasuraMetadata { unHM :: M.HashMap T.Text T.Text } deriving (Show)
instance ToJSON HasuraMetadata where
toJSON h = toJSON $ M.fromList $ map (first format) hdrs
where
hdrs = M.toList $ unHM h
format = T.map underscorify . T.drop 2
underscorify '-' = '_'
underscorify c = c
getHasuraMetadata :: Request -> Maybe Value
getHasuraMetadata req = case md of
[] -> Nothing
_ -> Just $ toJSON $ HasuraMetadata (M.fromList md)
where
md = filter filterFixedHeaders rawMd
filterFixedHeaders (h,_) = h /= userRoleHeader && h /= accessKeyHeader
rawMd = filter (\h -> "x-hasura-" `T.isInfixOf` fst h) hdrs
hdrs = map hdrToTxt $ requestHeaders req
hdrToTxt (k, v) = (T.toLower $ bsToTxt $ CI.original k, bsToTxt v)
-- | A type for IP address in numeric string representation.
type NumericAddress = String

2
server/src-lib/Hasura/Server/Query.hs
View File

@ -225,4 +225,4 @@ setHeadersTx userInfo =
toStrictText = LT.toStrict . AT.encodeToLazyText
setSess = Q.fromText $
"SET LOCAL \"hasura.user\" = " <>
pgFmtLit (toStrictText $ userHeaders userInfo)
pgFmtLit (toStrictText $ userVars userInfo)