[OPENIDM-15303] Scheduler is logging incorrect messages in openidm.log Created: 20/Aug/20  Updated: 19/Nov/20

Status: Open
Project: OpenIDM
Component/s: Module - Scheduler
Affects Version/s: 7.0.0
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Alexander Dracka Assignee: Brendan Miller
Resolution: Unresolved Votes: 0
Labels: CLARK
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: HTML File Scheduler_log_failure_FINEST_log     HTML File Scheduler_log_test_passed     HTML File scheduler_log_failure    
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.



 Comments   
Comment by Alexander Dracka [ 21/Aug/20 ]

Chris Drake I attached log with altered logging properties. Hopes it helps.

One thing: I am not running just the test but rather whole Suite, so my command looks like: -s *metrics openidm

Also you have to remove Tag OPENIDM-Unstable or you will miss the actual failure. And yes it takes some time to reproduce it but I would like to resolve this instead of marking these types of tests with Unstable Tag

Generated at Mon Nov 30 01:47:20 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.