Uploaded image for project: 'OpenIDM'
  1. OpenIDM
  2. OPENIDM-15303

Scheduler is logging incorrect messages in openidm.log

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 7.0.0
    • Fix Version/s: None
    • Component/s: Module - Scheduler
    • Labels:
    • Target Version/s:

      Description

      The best way to reproduce the issue: run pyforge test functional/services/metrics/metrics/scheduler_service_should_be_in_metrics.

      In the setup keyword: crud_on_additional_schedules test changed logging message for scheduler scripts: to Update1: and Update2:

      Failure is because missing expected logs:  

      Updated1:schedule firing up every second

      Updated2:schedule firing up every second

      After investigation I was able to reproduce this failure per ~30 executions of the test. There were missing either Updated1 or Updated2 keyword therefore it looks like one scheduler still logging with default message. Another failure was caused by the missing the whole message => eg. in openidm.log there was only Updated1:schedule firing up every second  (scheduler endpoint was configured correctly as Postman verified)

       

      This is the snippet of openidm.logs where is missing the logger message from second scheduler (Update2:..) 

      INFO: Updated1:schedule firing up every second [133] Aug 20, 2020 1:35:05.001 PM org.forgerock.openidm.util.LogUtil logAtLevel INFO: Scheduled service "scheduler-service-group.65a6b15f-ec66-40c7-9c84-c96422c8cf6d" invoke completed successfully. [134] Aug 20, 2020 1:35:06.002 PM org.forgerock.openidm.util.LogUtil logAtLevel INFO: Scheduled service "scheduler-service-group.65a6b15f-ec66-40c7-9c84-c96422c8cf6d" found, invoking. [134] Aug 20, 2020 1:35:06.003 PM org.forgerock.openidm.script.scope.FunctionFactory$3 call INFO: Updated1:schedule firing up every second [134] Aug 20, 2020 1:35:06.004 PM org.forgerock.openidm.util.LogUtil logAtLevel INFO: Scheduled service "scheduler-service-group.65a6b15f-ec66-40c7-9c84-c96422c8cf6d" invoke completed successfully. [135] Aug 20, 2020 1:35:07.003 PM org.forgerock.openidm.util.LogUtil logAtLevel INFO: Scheduled service "scheduler-service-group.65a6b15f-ec66-40c7-9c84-c96422c8cf6d" found, invoking. [135] Aug 20, 2020 1:35:07.004 PM org.forgerock.openidm.script.scope.FunctionFactory$3 call INFO: Updated1:schedule firing up every second
      

        I was able to query scheduler/job endpoint via Postman and verified that scheduler is configured correctly:

       

      {
          "result": [
              {
                  "_id": "65a6b15f-ec66-40c7-9c84-c96422c8cf6d",
                  "enabled": true,
                  "persisted": false,
                  "recoverable": false,
                  "misfirePolicy": "fireAndProceed",
                  "schedule": "                      *                        ?        ",
                  "repeatInterval": 0,
                  "repeatCount": 0,
                  "type": "cron",
                  "invokeService": "org.forgerock.openidm.script",
                  "invokeContext": {
                      "script": 

       

      {                     "type": "text/javascript",                     "source": "logger.info('Updated1:schedule firing up every second');"                 }

                  },
                  "invokeLogLevel": "info",
                  "startTime": null,
                  "endTime": null,
                  "concurrentExecution": false,
                  "triggers": [
                      {
                          "_id": "scheduler-service-group.trigger-65a6b15f-ec66-40c7-9c84-c96422c8cf6d",
                          "_rev": null,
                          "calendar": null,
                          "group": "scheduler-service-group",
                          "jobKey": "scheduler-service-group.65a6b15f-ec66-40c7-9c84-c96422c8cf6d",
                          "name": "trigger-65a6b15f-ec66-40c7-9c84-c96422c8cf6d",
                          "nodeId": null,
                          "previousState": null,
                          "serialized": {
                              "type": "CronTriggerImpl",
                              "calendarName": null,
                              "cronEx": 

      {                             "cronExpression": "* * * ? * *",                             "timeZone": "Europe/Prague"                         }

      ,
                              "description": null,
                              "endTime": null,
                              "fireInstanceId": "1597923288966",
                              "group": "scheduler-service-group",
                              "jobDataMap": null,
                              "jobGroup": "scheduler-service-group",
                              "jobName": "65a6b15f-ec66-40c7-9c84-c96422c8cf6d",
                              "misfireInstruction": 1,
                              "name": "trigger-65a6b15f-ec66-40c7-9c84-c96422c8cf6d",
                              "nextFireTime": 1597923643000,
                              "previousFireTime": 1597923642000,
                              "priority": 5,
                              "startTime": 1597923296000,
                              "volatility": false
                          },
                          "state": "NORMAL"
                      }
                  ],
                  "previousRunDate": "2020-08-20T11:40:42.000Z",
                  "nextRunDate": "2020-08-20T11:40:43.000Z"
              },
              {
                  "_id": "728977ec-0107-4209-a290-7be3b821ef2c",
                  "enabled": true,
                  "persisted": true,
                  "recoverable": false,
                  "misfirePolicy": "fireAndProceed",
                  "schedule": "                      *                        ?        ",
                  "repeatInterval": 0,
                  "repeatCount": 0,
                  "type": "cron",
                  "invokeService": "org.forgerock.openidm.script",
                  "invokeContext": {
                      "script": 

      {                     "type": "text/javascript",                     "source": "logger.info('Updated2:schedule firing up every second');"                 }

                  },
                  "invokeLogLevel": "info",
                  "startTime": null,
                  "endTime": null,
                  "concurrentExecution": false,
                  "triggers": [
                      {
                          "_id": "scheduler-service-group.trigger-728977ec-0107-4209-a290-7be3b821ef2c",
                          "_rev": "8",
                          "calendar": null,
                          "group": "scheduler-service-group",
                          "jobKey": "scheduler-service-group.728977ec-0107-4209-a290-7be3b821ef2c",
                          "name": "trigger-728977ec-0107-4209-a290-7be3b821ef2c",
                          "nodeId": "node1",
                          "previousState": null,
                          "serialized": {
                              "type": "CronTriggerImpl",
                              "calendarName": null,
                              "cronEx": 

      {                             "cronExpression": "* * * ? * *",                             "timeZone": "Europe/Prague"                         }

      ,
                              "description": null,
                              "endTime": null,
                              "fireInstanceId": null,
                              "group": "scheduler-service-group",
                              "jobDataMap": null,
                              "jobGroup": "scheduler-service-group",
                              "jobName": "728977ec-0107-4209-a290-7be3b821ef2c",
                              "misfireInstruction": 1,
                              "name": "trigger-728977ec-0107-4209-a290-7be3b821ef2c",
                              "nextFireTime": 1597923296000,
                              "previousFireTime": null,
                              "priority": 5,
                              "startTime": 1597923296000,
                              "volatility": false
                          },
                          "state": "NORMAL"
                      }
                  ],
                  "previousRunDate": null,
                  "nextRunDate": "2020-08-20T11:34:56.000Z"
              }
          ],
          "resultCount": 2,
          "pagedResultsCookie": null,
          "totalPagedResultsPolicy": "EXACT",
          "totalPagedResults": 2,
          "remainingPagedResults": -1
      }

      NOTE: This test is marked as Unstable and we are not able to fix test in some reasonable manner. Please check out logs I will gladly answer all your questions.

        Attachments

        1. scheduler_log_failure
          680 kB
          Alexander Dracka
        2. Scheduler_log_failure_FINEST_log
          221 kB
          Alexander Dracka
        3. Scheduler_log_test_passed
          237 kB
          Alexander Dracka

          Activity

            People

            • Assignee:
              brmiller Brendan Miller
              Reporter:
              alexander.dracka Alexander Dracka
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: