server: sanitise event trigger logs (fix hasura#1233)

- sanitise the response field in event trigger and scheduled trigger logs, removing the body and the headers - flatten the log structure to include the event id at `$.detail.event_id` instead of `$.detail.context.event_id` the log format changes as follows: ```diff diff --git a/log b/log index 96127e0..1fb909a 100644 --- a/log +++ b/log @@ -1,48 +1,15 @@ { "detail": { - "context": { - "event_id": "b9d4e627-6029-43f2-9d46-31c532b07070" - }, + "event_id": "adcc8dcd-2f32-4554-bd55-90c787aee137", "request": { "size": 416 }, "response": { - "body": "{\n \"args\": {}, \n \"data\": \"{\\\"event\\\":{\\\"session_variables\\\":{\\\"x-hasura-role\\\":\\\"admin\\\"},\\\"op\\\":\\\"INSERT\\\",\\\"data\\\":{\\\"old\\\":null,\\\"new\\\":{\\\"name\\\":\\\"someotheranimal\\\",\\\"id\\\":3}},\\\"trace_context\\\":{\\\"trace_id\\\":\\\"e8237c03de151634\\\",\\\"span_id\\\":\\\"8c5f8952e9e06da8\\\"}},\\\"created_at\\\":\\\"2021-05-06T07:52:58.796611Z\\\",\\\"id> - "headers": [ - { - "name": "Date", - "value": "Thu, 06 May 2021 07:53:00 GMT" - }, - { - "name": "Content-Type", - "value": "application/json" - }, - { - "name": "Content-Length", - "value": "1692" - }, - { - "name": "Connection", - "value": "keep-alive" - }, - { - "name": "Server", - "value": "gunicorn/19.9.0" - }, - { - "name": "Access-Control-Allow-Origin", - "value": "*" - }, - { - "name": "Access-Control-Allow-Credentials", - "value": "true" - } - ], - "size": 1692, + "size": 1719, "status": 200 } }, "level": "info", - "timestamp": "2021-05-06T13:23:00.376+0530", + "timestamp": "2021-05-06T13:25:14.481+0530", "type": "event-trigger" } ``` GitOrigin-RevId: d9622de
etrepum · May 12, 2021 · 04a8797 · 04a8797
1 parent 726c3e0
commit 04a8797
Show file tree

Hide file tree

Showing 7 changed files with 60 additions and 31 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -6,6 +6,7 @@
 
 (Add entries below in the order of: server, console, cli, docs, others)
 
+- server: sanitise event trigger and scheduled trigger logs to omit possibly sensitive request body and headers
 - server: fix parsing of values for Postgres char columns (fix #6814)
 - server: fix query execution of custom function containing a composite argument type
 - server: fix a bug in query validation that would cause some queries using default variable values to be rejected (fix #6867)

diff --git a/server/src-lib/Hasura/App.hs b/server/src-lib/Hasura/App.hs
@@ -525,6 +525,7 @@ runHGEServer setupHook env ServeOptions{..} ServeCtx{..} initTime postPollHook s
     fetchI        = milliseconds $ fromMaybe (Milliseconds defaultFetchInterval) soEventsFetchInterval
     logEnvHeaders = soLogHeadersFromEnv
     allPgSources  = mapMaybe (unsafeSourceConfiguration @('Postgres 'Vanilla)) $ HM.elems $ scSources $ lastBuiltSchemaCache _scSchemaCache
+    eventResponseLogBehaviour = if soInDevelopmentMode then LogEntireResponse else LogSanitisedResponse
 
   -- TODO: is this correct?
   -- event triggers should be tied to the life cycle of a source
@@ -550,6 +551,7 @@ runHGEServer setupHook env ServeOptions{..} ServeCtx{..} initTime postPollHook s
                         lockedEventsCtx
                         serverMetrics
                         soEnableMaintenanceMode
+                        eventResponseLogBehaviour
 
   -- start a backgroud thread to handle async actions
   case soAsyncActionsFetchInterval of
@@ -574,6 +576,7 @@ runHGEServer setupHook env ServeOptions{..} ServeCtx{..} initTime postPollHook s
   _scheduledEventsThread <- C.forkManagedT "processScheduledTriggers" logger $
     processScheduledTriggers env logger logEnvHeaders _scHttpManager
                              (getSCFromRef cacheRef) lockedEventsCtx
+                             eventResponseLogBehaviour
 
   -- start a background thread to check for updates
   _updateThread <- C.forkManagedT "checkForUpdates" logger $ liftIO $

diff --git a/server/src-lib/Hasura/Eventing/EventTrigger.hs b/server/src-lib/Hasura/Eventing/EventTrigger.hs
@@ -39,6 +39,7 @@ module Hasura.Eventing.EventTrigger
   , Event(..)
   , unlockEvents
   , EventEngineCtx(..)
+  , ResponseLogBehavior(..)
   ) where
 
 import           Hasura.Prelude
@@ -236,8 +237,9 @@ processEventQueue
   -> LockedEventsCtx
   -> ServerMetrics
   -> MaintenanceMode
+  -> ResponseLogBehavior
   -> m void
-processEventQueue logger logenv httpMgr getSchemaCache EventEngineCtx{..} LockedEventsCtx{leEvents} serverMetrics maintenanceMode = do
+processEventQueue logger logenv httpMgr getSchemaCache EventEngineCtx{..} LockedEventsCtx{leEvents} serverMetrics maintenanceMode responseLogBehavior = do
   events0 <- popEventsBatch
   -- Track number of events fetched in EKG
   _ <- liftIO $ EKG.Distribution.add (smNumEventsFetched serverMetrics) (fromIntegral $ length events0)
@@ -409,7 +411,7 @@ processEventQueue logger logenv httpMgr getSchemaCache EventEngineCtx{..} Locked
                       (liftIO $ EKG.Gauge.inc $ smNumEventHTTPWorkers serverMetrics)
                       (liftIO $ EKG.Gauge.dec $ smNumEventHTTPWorkers serverMetrics)
                       (runExceptT $ tryWebhook headers responseTimeout payload webhook)
-              logHTTPForET res extraLogCtx requestDetails
+              logHTTPForET res extraLogCtx requestDetails responseLogBehavior
               let decodedHeaders = map (decodeHeader logenv headerInfos) headers
               either
                 (processError sourceConfig e retryConf decodedHeaders ep maintenanceModeVersion)

diff --git a/server/src-lib/Hasura/Eventing/HTTP.hs b/server/src-lib/Hasura/Eventing/HTTP.hs
@@ -22,6 +22,7 @@ module Hasura.Eventing.HTTP
   , Invocation(..)
   , InvocationVersion
   , Response(..)
+  , ResponseLogBehavior(..)
   , WebhookRequest(..)
   , WebhookResponse(..)
   , ClientError(..)
@@ -43,6 +44,7 @@ module Hasura.Eventing.HTTP
 import qualified Data.ByteString               as BS
 import qualified Data.ByteString.Lazy          as LBS
 import qualified Data.CaseInsensitive          as CI
+import qualified Data.HashMap.Lazy             as HML
 import qualified Data.TByteString              as TBS
 import qualified Data.Text                     as T
 import qualified Data.Text.Encoding            as TE
@@ -140,8 +142,6 @@ data ExtraLogContext
   , elEventId        :: EventId
   } deriving (Show, Eq)
 
-$(deriveJSON hasuraJSON{omitNothingFields=True} ''ExtraLogContext)
-
 data HTTPResp (a :: TriggerTypes)
    = HTTPResp
    { hrsStatus  :: !Int
@@ -204,26 +204,41 @@ newtype RequestDetails
   = RequestDetails { _rdSize :: Int64 }
 $(deriveToJSON hasuraJSON ''RequestDetails)
 
+-- TODO(swann): move elsewhere? it could be useful more generally
+data ResponseLogBehavior = LogSanitisedResponse | LogEntireResponse
+  deriving (Show, Eq)
+
 data HTTPRespExtra (a :: TriggerTypes)
   = HTTPRespExtra
-  { _hreResponse :: !(Either (HTTPErr a) (HTTPResp a))
-  , _hreContext  :: !ExtraLogContext
-  , _hreRequest  :: !RequestDetails
+  { _hreResponse    :: !(Either (HTTPErr a) (HTTPResp a))
+  , _hreContext     :: !ExtraLogContext
+  , _hreRequest     :: !RequestDetails
+  , _hreLogResponse :: !ResponseLogBehavior
+  -- ^ Whether to log the entire response, including the body and the headers,
+  -- which may contain sensitive information.
   }
 
 instance ToJSON (HTTPRespExtra a) where
-  toJSON (HTTPRespExtra resp ctxt req) =
+  toJSON (HTTPRespExtra resp ctxt req logResp) =
     case resp of
-      Left errResp ->
-        object [ "response" .= toJSON errResp
-               , "request" .= toJSON req
-               , "context" .= toJSON ctxt
-               ]
-      Right rsp ->
-        object [ "response" .= toJSON rsp
-               , "request" .= toJSON req
-               , "context" .= toJSON ctxt
-               ]
+      Left errResp -> object
+        [ "response" .= toJSON errResp
+        , "request" .= toJSON req
+        , "event_id" .= elEventId ctxt
+        ]
+      Right okResp -> object
+        [ "response" .= case logResp of
+            LogEntireResponse    -> toJSON okResp
+            LogSanitisedResponse -> sanitisedRespJSON okResp
+        , "request" .= toJSON req
+        , "event_id" .= elEventId ctxt
+        ]
+    where
+      sanitisedRespJSON v
+        = Object $ HML.fromList
+        [ "size" .= hrsSize v
+        , "status" .= hrsStatus v
+        ]
 
 instance ToEngineLog (HTTPRespExtra 'EventType) Hasura where
   toEngineLog resp = (LevelInfo, eventTriggerLogType, toJSON resp)
@@ -274,10 +289,11 @@ logHTTPForET
   => Either (HTTPErr 'EventType) (HTTPResp 'EventType)
   -> ExtraLogContext
   -> RequestDetails
+  -> ResponseLogBehavior
   -> m ()
-logHTTPForET eitherResp extraLogCtx reqDetails = do
+logHTTPForET eitherResp extraLogCtx reqDetails logResp = do
   logger :: Logger Hasura <- asks getter
-  unLogger logger $ HTTPRespExtra eitherResp extraLogCtx reqDetails
+  unLogger logger $ HTTPRespExtra eitherResp extraLogCtx reqDetails logResp
 
 logHTTPForST
   :: ( MonadReader r m
@@ -287,10 +303,11 @@ logHTTPForST
   => Either (HTTPErr 'ScheduledType) (HTTPResp 'ScheduledType)
   -> ExtraLogContext
   -> RequestDetails
+  -> ResponseLogBehavior
   -> m ()
-logHTTPForST eitherResp extraLogCtx reqDetails = do
+logHTTPForST eitherResp extraLogCtx reqDetails logResp = do
   logger :: Logger Hasura <- asks getter
-  unLogger logger $ HTTPRespExtra eitherResp extraLogCtx reqDetails
+  unLogger logger $ HTTPRespExtra eitherResp extraLogCtx reqDetails logResp
 
 runHTTP :: (MonadIO m) => HTTP.Manager -> HTTP.Request -> m (Either (HTTPErr a) (HTTPResp a))
 runHTTP manager req = do

diff --git a/server/src-lib/Hasura/Eventing/ScheduledTrigger.hs b/server/src-lib/Hasura/Eventing/ScheduledTrigger.hs
@@ -228,8 +228,9 @@ processCronEvents
   -> [CronEvent]
   -> IO SchemaCache
   -> TVar (Set.Set CronEventId)
+  -> ResponseLogBehavior
   -> m ()
-processCronEvents logger logEnv httpMgr cronEvents getSC lockedCronEvents = do
+processCronEvents logger logEnv httpMgr cronEvents getSC lockedCronEvents responseLogBehavior = do
   cronTriggersInfo <- scCronTriggers <$> liftIO getSC
   -- save the locked cron events that have been fetched from the
   -- database, the events stored here will be unlocked in case a
@@ -248,7 +249,7 @@ processCronEvents logger logEnv httpMgr cronEvents getSC lockedCronEvents = do
             retryCtx = RetryContext tries ctiRetryConf
         finally <- runMetadataStorageT $ flip runReaderT (logger, httpMgr) $
                    processScheduledEvent logEnv id' ctiHeaders retryCtx
-                                         payload webhookUrl Cron
+                                         payload webhookUrl Cron responseLogBehavior
         removeEventFromLockedEvents id' lockedCronEvents
         onLeft finally logInternalError
   where
@@ -266,9 +267,10 @@ processOneOffScheduledEvents
   -> HTTP.Manager
   -> [OneOffScheduledEvent]
   -> TVar (Set.Set OneOffScheduledEventId)
+  -> ResponseLogBehavior
   -> m ()
 processOneOffScheduledEvents env logger logEnv httpMgr
-                             oneOffEvents lockedOneOffScheduledEvents = do
+                             oneOffEvents lockedOneOffScheduledEvents responseLogBehavior = do
   -- save the locked one-off events that have been fetched from the
   -- database, the events stored here will be unlocked in case a
   -- graceful shutdown is initiated in midst of processing these events
@@ -284,7 +286,7 @@ processOneOffScheduledEvents env logger logEnv httpMgr
           retryCtx = RetryContext _ooseTries _ooseRetryConf
 
       flip runReaderT (logger, httpMgr) $
-        processScheduledEvent logEnv _ooseId headerInfo retryCtx payload webhookUrl OneOff
+        processScheduledEvent logEnv _ooseId headerInfo retryCtx payload webhookUrl OneOff responseLogBehavior
       removeEventFromLockedEvents _ooseId lockedOneOffScheduledEvents
   where
     logInternalError err = liftIO . L.unLogger logger $ ScheduledTriggerInternalErr err
@@ -301,15 +303,16 @@ processScheduledTriggers
   -> HTTP.Manager
   -> IO SchemaCache
   -> LockedEventsCtx
+  -> ResponseLogBehavior
   -> m void
-processScheduledTriggers env logger logEnv httpMgr getSC LockedEventsCtx {..} =
+processScheduledTriggers env logger logEnv httpMgr getSC LockedEventsCtx {..} responseLogBehavior =
   forever $ do
     result <- runMetadataStorageT getScheduledEventsForDelivery
     case result of
       Left e -> logInternalError e
       Right (cronEvents, oneOffEvents) -> do
-        processCronEvents logger logEnv httpMgr cronEvents getSC leCronEvents
-        processOneOffScheduledEvents env logger logEnv httpMgr oneOffEvents leOneOffEvents
+        processCronEvents logger logEnv httpMgr cronEvents getSC leCronEvents responseLogBehavior
+        processOneOffScheduledEvents env logger logEnv httpMgr oneOffEvents leOneOffEvents responseLogBehavior
     -- NOTE: cron events are scheduled at times with minute resolution (as on
     -- unix), while one-off events can be set for arbitrary times. The sleep
     -- time here determines how overdue a scheduled event (cron or one-off)
@@ -334,8 +337,9 @@ processScheduledEvent
   -> ScheduledEventWebhookPayload
   -> Text
   -> ScheduledEventType
+  -> ResponseLogBehavior
   -> m ()
-processScheduledEvent logEnv eventId eventHeaders retryCtx payload webhookUrl type'
+processScheduledEvent logEnv eventId eventHeaders retryCtx payload webhookUrl type' responseLogBehavior
                       = Tracing.runTraceT traceNote do
   currentTime <- liftIO getCurrentTime
   let retryConf = _rctxConf retryCtx
@@ -353,7 +357,7 @@ processScheduledEvent logEnv eventId eventHeaders retryCtx payload webhookUrl ty
           webhookReqBody = J.encode webhookReqBodyJson
           requestDetails = RequestDetails $ BL.length webhookReqBody
       eitherRes <- runExceptT $ tryWebhook headers httpTimeout webhookReqBody (T.unpack webhookUrl)
-      logHTTPForST eitherRes extraLogCtx requestDetails
+      logHTTPForST eitherRes extraLogCtx requestDetails responseLogBehavior
       let decodedHeaders = map (decodeHeader logEnv eventHeaders) headers
       case eitherRes of
         Left e  -> processError eventId retryCtx decodedHeaders type' webhookReqBodyJson e

diff --git a/server/src-lib/Hasura/Server/Init.hs b/server/src-lib/Hasura/Server/Init.hs
@@ -252,6 +252,7 @@ mkServeOptions rso = do
            schemaPollInterval
            experimentalFeatures
            eventsFetchBatchSize
+           devMode
   where
 #ifdef DeveloperAPIs
     defaultAPIs = [METADATA,GRAPHQL,PGDUMP,CONFIG,DEVELOPER]

diff --git a/server/src-lib/Hasura/Server/Init/Config.hs b/server/src-lib/Hasura/Server/Init/Config.hs
@@ -163,6 +163,7 @@ data ServeOptions impl
   , soSchemaPollInterval            :: !OptionalInterval
   , soExperimentalFeatures          :: !(Set.HashSet ExperimentalFeature)
   , soEventsFetchBatchSize          :: !NonNegativeInt
+  , soInDevelopmentMode             :: !Bool
   }
 
 data DowngradeOptions