Scheduler job stops to repeat every day at about 00:00AM

[ArtUrlWWW]

Hello.

I have a very simple code, that runs jobs from plugin.

Initially it was a job, started directly in Quartz. But it always stopped to repeat every day at 00:00AM.

OK, I reworked to job for SchedulerService:

Code, that called job

SchedulerService schedulerService = ComponentAccessor.getComponent(SchedulerService.class);

Vars.sjr = new SyncJobRunner(schedulerService);

and job code is

package arthur.khusnutdinov.jira.plugins.lotus.bridge.eventlisteners;

import com.atlassian.scheduler.JobRunner;
import com.atlassian.scheduler.JobRunnerRequest;
import com.atlassian.scheduler.JobRunnerResponse;
import com.atlassian.scheduler.SchedulerService;
import com.atlassian.scheduler.SchedulerServiceException;
import com.atlassian.scheduler.config.JobConfig;
import com.atlassian.scheduler.config.JobId;
import com.atlassian.scheduler.config.JobRunnerKey;
import com.atlassian.scheduler.config.RunMode;
import com.atlassian.scheduler.config.Schedule;
import com.atlassian.scheduler.status.JobDetails;
import java.util.Date;
import java.util.Random;
import org.springframework.beans.factory.DisposableBean;
import org.springframework.beans.factory.InitializingBean;

/**
*
* @author Husnutdinov
*/
public class SyncJobRunner implements JobRunner, InitializingBean, DisposableBean {

private final SchedulerService schedulerService;
private static final long SCHEDULE_BASE_INTERVAL_MILLIS = 6000L;
private static final JobRunnerKey JOB = JobRunnerKey.of(SyncJobRunner.class.getName());
private static final Random RANDOM = new Random();
private static final int SCHEDULE_MAX_JITTER = 10000;
private static final String JOB_ID_PREFIX = "Job ID =";

// public SyncJobRunner() {
// }
public SyncJobRunner(SchedulerService schedulerService) {
System.out.println("!!! SyncJobRunner 2");
this.schedulerService = schedulerService;
schedulerService.registerJobRunner(JOB, this);
try {
this.createSchedule(1, SCHEDULE_BASE_INTERVAL_MILLIS);

} catch (Exception e) {
}
}

@Override
public void afterPropertiesSet() throws Exception {
System.out.println("!!!!!!!!!! afterPropertiesSet");
schedulerService.registerJobRunner(JOB, this);
createSchedule(1, SCHEDULE_BASE_INTERVAL_MILLIS);
}

@Override
public JobRunnerResponse runJob(JobRunnerRequest request) {
try {
System.out.println("!!!!!!!!!!!!!! Job A");

SyncJobWorker sjw = new SyncJobWorker();
sjw.execute();

return JobRunnerResponse.success();
} catch (Exception e) {
return JobRunnerResponse.failed(e);
}
}

@Override
public void destroy() throws Exception {
System.out.println("!!!!!!!!! SyncJobRunner.destroy()");
int jobID = 1;
final JobId jobId = toJobId(jobID);
final JobDetails existing = schedulerService.getJobDetails(jobId);
if (existing != null) {
System.out.println("!!!!!!!!! SyncJobRunner.destroy() - existing");
schedulerService.unscheduleJob(jobId);
}

this.schedulerService.unregisterJobRunner(JOB);
}

public void createSchedule(int jobID, long intervalInMillis) throws Exception {
final int jitter = RANDOM.nextInt(SCHEDULE_MAX_JITTER);
final Date firstRun = new Date(System.currentTimeMillis() + jitter);
final JobConfig jobConfig = JobConfig.forJobRunnerKey(JOB)
.withSchedule(Schedule.forInterval(intervalInMillis, firstRun))
.withRunMode(RunMode.RUN_ONCE_PER_CLUSTER);
try {
final JobId jobId = toJobId(jobID);
final JobDetails existing = schedulerService.getJobDetails(jobId);
if (existing != null) {
schedulerService.unscheduleJob(jobId);
}
schedulerService.scheduleJob(jobId, jobConfig);
} catch (SchedulerServiceException sse) {
throw new Exception("Unable to create schedule for job ID '" + jobID + '\'', sse);
}
}

private static JobId toJobId(int jobID) {
return JobId.of(JOB_ID_PREFIX + jobID);
}

}

But this realization have a same bug - it stops to repeat every day at about 00:00.

And looks like something stops execution of the job at the middle of it's execution! Every execution of my job prints "Step DONE" at the end of it's execution, but the latest execution didn't printed "Step DONE" in Jira log:

...some log of correct execution here and before...

Step 5
Step 6
Step 5
Step 6
Step DONE - yep, exectuion was correctly ended
2018-11-23 00:00:24,881 Caesium-1-1 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting changeUsers
2018-11-23 00:00:25,362 Caesium-1-1 INFO admin [c.a.j.issue.index.DefaultIndexManager] ReindexAll in foreground: {indexIssues=true, indexChangeHistory=true, indexComments=true, indexWorklogs=true, forceReloadFromDatabase=false}
2018-11-23 00:00:25,362 Caesium-1-1 WARN admin [c.a.s.p.c.internal.index.CannedResponseIndexLauncherImpl] Canned Response 'REINDEX ALL EVENT' is about to start FOREGROUND reindex all
2018-11-23 00:00:25,369 Caesium-1-1 WARN admin [c.a.s.p.c.internal.index.CannedResponseIndexLauncherImpl] Canned Response REINDEX ALL EVENT has finished FOREGROUND reindex all
2018-11-23 00:00:50,491 Caesium-1-1 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] *********** JOB DONE!!!! - yep, exectuion was correctly ended
!!!!!!!!!!!!!! Job A
2018-11-23 00:02:04,045 Caesium-1-4 INFO ServiceRunner [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] ++++++ JOB IS WORKING NOW!!!! - started again at 00:02
2018-11-23 00:02:04,072 Caesium-1-4 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting CreateProjects
2018-11-23 00:02:04,072 Caesium-1-4 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting checkIssuesPriorities
2018-11-23 00:02:04,230 Caesium-1-4 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting syncDeps
2018-11-23 00:02:05,472 Caesium-1-4 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting syncUsers
2018-11-23 00:02:15,650 Caesium-1-4 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting syncIssues
2018-11-23 00:02:17,452 Caesium-1-4 INFO admin [c.a.j.issue.index.DefaultIndexManager] ReindexAll in foreground: {indexIssues=true, indexChangeHistory=true, indexComments=true, indexWorklogs=true, forceReloadFromDatabase=false}
2018-11-23 00:02:17,452 Caesium-1-4 WARN admin [c.a.s.p.c.internal.index.CannedResponseIndexLauncherImpl] Canned Response 'REINDEX ALL EVENT' is about to start FOREGROUND reindex all
2018-11-23 00:02:17,461 Caesium-1-4 WARN admin [c.a.s.p.c.internal.index.CannedResponseIndexLauncherImpl] Canned Response REINDEX ALL EVENT has finished FOREGROUND reindex all
2018-11-23 00:02:27,173 Caesium-1-4 INFO admin [a.k.j.p.l.bridge.eventlisteners.SyncJobWorker] Starting checkClosedIssues
Step 1
Step 2
Step 3
Step 4
Step 5
Step 6
Step 5
Step 6
Step 5

-- and something happens at this moment, job execution was breaked, no"OB DONE!!!!" and "Step DONE" messages.
23-Nov-2018 00:14:05.884 WARNING [http-nio-8080-exec-24] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 00:29:05.882 WARNING [http-nio-8080-exec-22] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
2018-11-23 00:37:27,652 Caesium-1-2 INFO ServiceRunner [c.a.j.p.h.service.ping.RefreshConnectionStatusJobHandler] Running RefreshConnectionStatusJobHandler...
2018-11-23 00:37:33,226 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] Running InstallGlancesJobHandler...
2018-11-23 00:37:33,226 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] There is no link to HipChat, no need to install glances.
2018-11-23 00:38:10,536 HealthCheck:thread-4 WARN [c.a.applinks.core.DefaultApplinkStatusService] Unrecognized error while attempting to retrieve status of Application Link '60935439-5971-335c-87ef-c89d8ad42934'
23-Nov-2018 00:44:05.883 WARNING [http-nio-8080-exec-24] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 00:59:05.904 WARNING [http-nio-8080-exec-23] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 01:14:05.877 WARNING [http-nio-8080-exec-5] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproje
23-Nov-2018 01:29:05.874 WARNING [http-nio-8080-exec-22] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
2018-11-23 01:37:27,661 Caesium-1-1 INFO ServiceRunner [c.a.j.p.h.service.ping.RefreshConnectionStatusJobHandler] Running RefreshConnectionStatusJobHandler...
2018-11-23 01:37:33,227 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] Running InstallGlancesJobHandler...
2018-11-23 01:37:33,227 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] There is no link to HipChat, no need to install glances.
2018-11-23 01:38:10,495 HealthCheck:thread-5 WARN [c.a.applinks.core.DefaultApplinkStatusService] Unrecognized error while attempting to retrieve status of Application Link '60935439-5971-335c-87ef-c89d8ad42934'
23-Nov-2018 01:44:05.871 WARNING [http-nio-8080-exec-24] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 01:59:05.872 WARNING [http-nio-8080-exec-23] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 02:14:05.865 WARNING [http-nio-8080-exec-24] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 02:29:05.866 WARNING [http-nio-8080-exec-23] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
2018-11-23 02:37:27,653 Caesium-1-1 INFO ServiceRunner [c.a.j.p.h.service.ping.RefreshConnectionStatusJobHandler] Running RefreshConnectionStatusJobHandler...
2018-11-23 02:37:33,226 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] Running InstallGlancesJobHandler...
2018-11-23 02:37:33,226 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] There is no link to HipChat, no need to install glances.
2018-11-23 02:38:10,519 HealthCheck:thread-5 WARN [c.a.applinks.core.DefaultApplinkStatusService] Unrecognized error while attempting to retrieve status of Application Link '60935439-5971-335c-87ef-c89d8ad42934'
23-Nov-2018 02:44:05.889 WARNING [http-nio-8080-exec-24] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 02:59:05.884 WARNING [http-nio-8080-exec-22] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproj
23-Nov-2018 03:14:05.854 WARNING [http-nio-8080-exec-8] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproje
23-Nov-2018 03:29:05.853 WARNING [http-nio-8080-exec-7] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproje
2018-11-23 03:37:27,650 Caesium-1-3 INFO ServiceRunner [c.a.j.p.h.service.ping.RefreshConnectionStatusJobHandler] Running RefreshConnectionStatusJobHandler...
2018-11-23 03:37:33,225 Caesium-1-1 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] Running InstallGlancesJobHandler...
2018-11-23 03:37:33,225 Caesium-1-1 INFO ServiceRunner [c.a.j.p.h.service.connect.InstallGlancesJobHandler] There is no link to HipChat, no need to install glances.
2018-11-23 03:38:10,487 HealthCheck:thread-5 WARN [c.a.applinks.core.DefaultApplinkStatusService] Unrecognized error while attempting to retrieve status of Application Link '60935439-5971-335c-87ef-c89d8ad42934'
23-Nov-2018 03:44:05.853 WARNING [http-nio-8080-exec-1] com.sun.jersey.spi.container.servlet.WebComponent.filterFormParameters A servlet request, to the URI http://jira:8080/rest/gadget/1.0/project/generate?projectsOrCategories=allproje
2018-11-23 03:50:02,062 Caesium-1-3 INFO anonymous Backup Service [c.a.j.bc.dataimport.DefaultExportService] Data export completed in 2019ms. Wrote 72895 entities to export in memory.
2018-11-23 03:50:02,064 Caesium-1-3 INFO anonymous Backup Service [c.a.j.bc.dataimport.DefaultExportService] Attempting to save the Active Objects Backup
2018-11-23 03:50:06,825 Caesium-1-3 INFO anonymous Backup Service [c.a.j.bc.dataimport.DefaultExportService] Finished saving the Active Objects Backup

When I look at "Scheduler administration" in admin panel of Jira, I see:

Job ID =1 5 milliseconds 1 minute Show less

Group
arthur.khusnutdinov.jira.plugins.lotus.bridge.eventlisteners.SyncJobRunner
Type
Runnable
Parameters
{}
Run mode
once per cluster
Schedule
1 minute
Last run
Fri Nov 23 11:55:51 UTC 2018
Last run duration
5 milliseconds
Next run
Fri Nov 23 11:56:51 UTC 2018
Message
Already running

So, Last run was at Fri Nov 23 11:55:51 UTC 2018, but now is Fri Nov 23 11:55:51 UTC 2018.

OK, Looks, like it's tried to start, but there are no execution results of Job in the database and no log output of the job.

What's happened in this case and how to fix that?