server: log when cron triggers are fetched from database for generating events

PR-URL: https://github.com/hasura/graphql-engine-mono/pull/7725 Co-authored-by: Rob Dominguez <24390149+robertjdominguez@users.noreply.github.com> GitOrigin-RevId: 8dd2b07c769392e057400c5e60e40e7fc56ac26f
2024-12-14 17:02:49 +03:00 · 2023-02-07 17:52:08 +05:30 · 2023-02-07 17:52:08 +05:30 · e6c5a9505b
commit e6c5a9505b
parent 36a9de5215
5 changed files with 125 additions and 13 deletions
--- a/docs/docs/deployment/logging.mdx
+++ b/docs/docs/deployment/logging.mdx
@ -61,17 +61,18 @@ All the log-types that can be enabled/disabled are:

 Apart from the above, there are other internal log-types which cannot be configured:

-| Log type                    | Description                                                                                         | Log Level          |
-|-----------------------------|-----------------------------------------------------------------------------------------------------|--------------------|
-| `pg-client`                 | Logs from the postgres client library                                                               | `warn`             |
-| `metadata`                  | Logs inconsistent Metadata items                                                                    | `warn`             |
-| `telemetry-log`             | Logs error (if any) while sending out telemetry data                                                | `info`             |
-| `event-trigger`             | Logs HTTP responses from the webhook, HTTP exceptions and internal errors                           | `info` and `error` |
-| `ws-server`                 | Debug logs from the websocket server, mostly used internally for debugging                          | `debug`            |
-| `schema-sync-thread`        | Logs internal events, when it detects schema has changed on Postgres and when it reloads the schema | `info` and `error` |
-| `health-check-log`          | Logs source Health Check events which includes health status of a data source                       | `info` and `warn`  |
-| `event-trigger-process`     | Logs the statistics of events fetched from database for each source                                 | `info` and `warn`  |
-| `scheduled-trigger-process` | Logs the statistics of scheduled and cron events fetched from metadata storage                      | `info` and `warn`  |
+| Log type                       | Description                                                                                         | Log Level          |
+|--------------------------------|-----------------------------------------------------------------------------------------------------|--------------------|
+| `pg-client`                    | Logs from the postgres client library                                                               | `warn`             |
+| `metadata`                     | Logs inconsistent Metadata items                                                                    | `warn`             |
+| `telemetry-log`                | Logs error (if any) while sending out telemetry data                                                | `info`             |
+| `event-trigger`                | Logs HTTP responses from the webhook, HTTP exceptions and internal errors                           | `info` and `error` |
+| `ws-server`                    | Debug logs from the websocket server, mostly used internally for debugging                          | `debug`            |
+| `schema-sync-thread`           | Logs internal events, when it detects schema has changed on Postgres and when it reloads the schema | `info` and `error` |
+| `health-check-log`             | Logs source Health Check events which includes health status of a data source                       | `info` and `warn`  |
+| `event-trigger-process`        | Logs the statistics of events fetched from database for each source                                 | `info` and `warn`  |
+| `scheduled-trigger-process`    | Logs the statistics of scheduled and cron events fetched from metadata storage                      | `info` and `warn`  |
+| `cron-event-generator-process` | Logs the cron triggers fetched from metadata storage for events generation                          | `info` and `warn`  |


 ## Logging levels
@ -594,6 +595,53 @@ The `detail` field value is an object contains the following members.
 | `num_one_off_scheduled_events_fetched` | int                        | The count of total one-off scheduled events fetched    |
 | `num_fetches`                          | int                        | The number of fetches happened within 10 minutes       |

+### **cron-event-generator-process** log structure
+
+Every 10 minutes, the Hasura Engine logs the cron triggers fetched from metadata storage for events generation. The
+log also contains the number of times new triggers are fetched within the 10 minute timeframe.
+
+```json
+{
+  "detail": {
+    "cron_triggers": [
+      {
+        "max_scheduled_time": "2023-01-31T13:18:00Z",
+        "name": "every_two_minutes",
+        "upcoming_events_count": 99
+      }
+    ],
+    "num_fetches": 10
+  },
+  "level": "info",
+  "timestamp": "2023-01-31T15:31:55.773+0530",
+  "type": "cron-event-generator-process"
+}
+```
+The `type` in the log will be `cron-event-generator-process` and details of the cron event generator process will be
+under the `detail` key.
+
+The `detail` field value is an object containing the following members.
+
+| Name            | Type                               | Description                                      |
+|-----------------|------------------------------------|--------------------------------------------------|
+| `cron_triggers` | List of `CronTriggerStats` objects | The list of cron triggers fetched                |
+| `num_fetches`   | int                                | The number of fetches happened within 10 minutes |
+
+The `CronTriggerStats` object contains the following members.
+
+| Name                    | Type   | Description                                    |
+|-------------------------|--------|------------------------------------------------|
+| `name`                  | string | The name of the cron trigger                   |
+| `upcoming_events_count` | int    | The number of undelivered upcoming cron events |
+| `max_scheduled_time`    | string | The timestamp of the cron event occurring last |
+
+:::info Note
+
+A new set of cron events will be generated only for triggers with fewer than 100 upcoming events.
+Thus, the `upcoming_events_count` will be always `< 100`.
+
+:::
+
 ## Monitoring frameworks

 You can integrate the logs emitted by the Hasura Engine with external monitoring tools for better visibility as per your
--- a/server/src-lib/Hasura/App.hs
+++ b/server/src-lib/Hasura/App.hs
@ -786,10 +786,16 @@ mkHGEServer setupHook env ServeOptions {..} serverCtx@ServerCtx {..} ekgStore ch
      startEventTriggerPollerThread logger lockedEventsCtx cacheRef
      startAsyncActionsPollerThread logger lockedEventsCtx cacheRef actionSubState

+      -- Create logger for logging the statistics of fetched cron triggers
+      fetchedCronTriggerStatsLogger <-
+        allocate
+          (createFetchedCronTriggerStatsLogger logger)
+          (closeFetchedCronTriggersStatsLogger logger)
+
      -- start a background thread to create new cron events
      _cronEventsThread <-
        C.forkManagedT "runCronEventsGenerator" logger $
-          runCronEventsGenerator logger (getSchemaCache cacheRef)
+          runCronEventsGenerator logger fetchedCronTriggerStatsLogger (getSchemaCache cacheRef)

      startScheduledEventsPollerThread logger lockedEventsCtx cacheRef
    EventingDisabled ->
--- a/server/src-lib/Hasura/Eventing/ScheduledTrigger.hs
+++ b/server/src-lib/Hasura/Eventing/ScheduledTrigger.hs
@ -78,6 +78,10 @@ module Hasura.Eventing.ScheduledTrigger
    CronEventSeed (..),
    LockedEventsCtx (..),

+    -- * Cron trigger stats logger
+    createFetchedCronTriggerStatsLogger,
+    closeFetchedCronTriggersStatsLogger,
+
    -- * Scheduled events stats logger
    createFetchedScheduledEventsStatsLogger,
    closeFetchedScheduledEventsStatsLogger,
@ -166,9 +170,10 @@ runCronEventsGenerator ::
    MonadMetadataStorage m
  ) =>
  L.Logger L.Hasura ->
+  FetchedCronTriggerStatsLogger ->
  IO SchemaCache ->
  m void
-runCronEventsGenerator logger getSC = do
+runCronEventsGenerator logger cronTriggerStatsLogger getSC = do
  forever $ do
    sc <- liftIO getSC
    -- get cron triggers from cache
@ -181,6 +186,8 @@ runCronEventsGenerator logger getSC = do
      -- When shutdown is initiated, we stop generating new cron events
      eitherRes <- runExceptT $ do
        deprivedCronTriggerStats <- liftEitherM $ getDeprivedCronTriggerStats $ Map.keys cronTriggersCache
+        -- Log fetched deprived cron trigger stats
+        logFetchedCronTriggersStats cronTriggerStatsLogger deprivedCronTriggerStats
        -- join stats with cron triggers and produce @[(CronTriggerInfo, CronTriggerStats)]@
        cronTriggersForHydrationWithStats <-
          catMaybes
@ -1109,3 +1116,23 @@ logFetchedScheduledEventsStats ::
  m ()
 logFetchedScheduledEventsStats logger cron oneOff =
  logStats logger (FetchedScheduledEventsStats cron oneOff 1)
+
+-- | Logger to accumulate stats of fetched cron triggers, for generating cron events, over a period of time and
+-- log once using @'L.Logger L.Hasura'.
+-- See @'createStatsLogger' for more details.
+createFetchedCronTriggerStatsLogger :: (MonadIO m) => L.Logger L.Hasura -> m FetchedCronTriggerStatsLogger
+createFetchedCronTriggerStatsLogger = createStatsLogger
+
+-- | Close the fetched cron trigger stats logger.
+closeFetchedCronTriggersStatsLogger ::
+  (MonadIO m) => L.Logger L.Hasura -> FetchedCronTriggerStatsLogger -> m ()
+closeFetchedCronTriggersStatsLogger = closeStatsLogger L.cronEventGeneratorProcessType
+
+-- | Log statistics of fetched cron triggers. See @'logStats' for more details.
+logFetchedCronTriggersStats ::
+  (MonadIO m) =>
+  FetchedCronTriggerStatsLogger ->
+  [CronTriggerStats] ->
+  m ()
+logFetchedCronTriggersStats logger cronTriggerStats =
+  logStats logger (FetchedCronTriggerStats cronTriggerStats 1)
--- a/server/src-lib/Hasura/Eventing/ScheduledTrigger/Types.hs
+++ b/server/src-lib/Hasura/Eventing/ScheduledTrigger/Types.hs
@ -2,6 +2,8 @@

 module Hasura.Eventing.ScheduledTrigger.Types
  ( CronTriggerStats (CronTriggerStats, _ctsMaxScheduledTime, _ctsName),
+    FetchedCronTriggerStats (..),
+    FetchedCronTriggerStatsLogger,
    RetryContext (RetryContext, _rctxConf),
    ScheduledEventOp (..),
    ScheduledEventWebhookPayload (ScheduledEventWebhookPayload, sewpName, sewpScheduledTime, sewpRequestTransform, sewpResponseTransform),
@ -40,6 +42,29 @@ data CronTriggerStats = CronTriggerStats
  }
  deriving (Eq)

+$(J.deriveToJSON hasuraJSON ''CronTriggerStats)
+
+data FetchedCronTriggerStats = FetchedCronTriggerStats
+  { _fctsCronTriggers :: [CronTriggerStats],
+    _fctsNumFetches :: Int
+  }
+  deriving (Eq)
+
+$(J.deriveToJSON hasuraJSON ''FetchedCronTriggerStats)
+
+instance L.ToEngineLog FetchedCronTriggerStats L.Hasura where
+  toEngineLog stats =
+    (L.LevelInfo, L.cronEventGeneratorProcessType, J.toJSON stats)
+
+instance Semigroup FetchedCronTriggerStats where
+  (FetchedCronTriggerStats lTriggers lFetches) <> (FetchedCronTriggerStats rTriggers rFetches) =
+    FetchedCronTriggerStats (lTriggers <> rTriggers) (lFetches + rFetches)
+
+instance Monoid FetchedCronTriggerStats where
+  mempty = FetchedCronTriggerStats mempty 0
+
+type FetchedCronTriggerStatsLogger = FDebounce.Trigger FetchedCronTriggerStats FetchedCronTriggerStats
+
 data RetryContext = RetryContext
  { _rctxTries :: !Int,
    _rctxConf :: !STRetryConf
--- a/server/src-lib/Hasura/Logging.hs
+++ b/server/src-lib/Hasura/Logging.hs
@ -25,6 +25,7 @@ module Hasura.Logging
    eventTriggerProcessLogType,
    scheduledTriggerLogType,
    scheduledTriggerProcessLogType,
+    cronEventGeneratorProcessType,
    sourceCatalogMigrationLogType,
    EnabledLogTypes (..),
    defaultEnabledEngineLogTypes,
@ -123,6 +124,7 @@ data InternalLogTypes
  | ILTEventTriggerProcess
  | ILTScheduledTrigger
  | ILTScheduledTriggerProcess
+  | ILTCronEventGeneratorProcess
  | -- | internal logs for the websocket server
    ILTWsServer
  | ILTPgClient
@ -142,6 +144,7 @@ instance Witch.From InternalLogTypes Text where
    ILTEventTriggerProcess -> "event-trigger-process"
    ILTScheduledTrigger -> "scheduled-trigger"
    ILTScheduledTriggerProcess -> "scheduled-trigger-process"
+    ILTCronEventGeneratorProcess -> "cron-event-generator-process"
    ILTWsServer -> "ws-server"
    ILTPgClient -> "pg-client"
    ILTMetadata -> "metadata"
@ -324,5 +327,8 @@ scheduledTriggerLogType = ELTInternal ILTScheduledTrigger
 scheduledTriggerProcessLogType :: EngineLogType Hasura
 scheduledTriggerProcessLogType = ELTInternal ILTScheduledTriggerProcess

+cronEventGeneratorProcessType :: EngineLogType Hasura
+cronEventGeneratorProcessType = ELTInternal ILTCronEventGeneratorProcess
+
 sourceCatalogMigrationLogType :: EngineLogType Hasura
 sourceCatalogMigrationLogType = ELTInternal ILTSourceCatalogMigration