Why is Spring Batch scheduled job running only once, though the scheduler runs and job listener says FINISHED every run

1
votes

I have created Spring Batch(RESTReader, custom processor and custom ItemWriter) I scheduled it. Spring Batch works fine. Scheduling seems to work as the listener prints job finished for every scheduled interval, but doesn't seem to read or write.

My Sprint Boot Application

      @EnableScheduling
      @SpringBootApplication
      public class BatchApplication {
         public static void main(String[] args) {
            SpringApplication.run(BatchApplication.class,args);        
         }  
      }

My Job scheduler

@Component
public class BatchScheduler {
    Logger log = Logger.getLogger(BatchScheduler.class);
     @Autowired
        private JobLauncher jobLauncher;
     @Autowired
     private JobCompletionNotificationListener listener;
     @Autowired
        private Step step1;
     @Autowired
        public JobBuilderFactory jobBuilderFactory;
     @Autowired
     private CreateRegistrationsBatchConfiguration job;
     @Scheduled(fixedRate = 85000)
     public void runJob() {
        try{
            JobExecution execution = jobLauncher.run(

                job.importRegistrationJob(jobBuilderFactory, listener, 
            step1),
            new JobParametersBuilder().addLong("uniqueness", 
            System.nanoTime()).toJobParameters()
        );
        log.info("Job finished with status :" + execution.getStatus());
        }catch(Exception exception) {
            log.error(exception.getMessage());
        }
    }
}

My Spring Batch Configuration

@Configuration
@EnableBatchProcessing

public class CreateRegistrationsBatchConfiguration {
    Logger log = 
      Logger.getLogger(CreateRegistrationsBatchConfiguration.class);
    @Autowired
    public JobBuilderFactory jobBuilderFactory;

    @Autowired
    public StepBuilderFactory stepBuilderFactory;

    @Autowired
    private Environment environment;

    @Bean
    RestTemplate restTemplate() {
        return new RestTemplate();
    }

    @Bean
    ItemReader<EmployeeEmploymentDTO> restEmployeeReader(Environment 
           environment, 
                                             RestTemplate restTemplate) {
        return new RESTEmployeeReader(


   environment.getRequiredProperty("rest.api.url"), 
            restTemplate
        );
    }

    @Bean
    public RegistrationItemProcessor processor() {
        return new RegistrationItemProcessor();
    }

    @Bean
    public ItemWriter<List<Registration>> writer() {
        return new MultiOutputItemWriter();
    }

    @Bean
    public Job importRegistrationJob(JobBuilderFactory jobs, JobCompletionNotificationListener listener, Step step1) {
        return jobBuilderFactory.get("importRegistrationJob")
            .incrementer(new RunIdIncrementer())
            .listener(listener)
            .flow(step1)
            .end()
            .build();
    }

    @Bean
    public Step step1(StepBuilderFactory stepBuilderFactory, 
     ItemReader<EmployeeEmploymentDTO> reader,
            ItemWriter<List<Registration>> writer, 
          ItemProcessor<EmployeeEmploymentDTO, List<Registration>> 
          processor) {
        return stepBuilderFactory.get("step1").allowStartIfComplete(true)
            .<EmployeeEmploymentDTO, List<Registration>> chunk(10)
            .reader(restEmployeeReader(environment,restTemplate()))           
            .processor(processor())
            .writer(writer)           
            .build();
    }     
 }

Batch Table Data batch_job_execution

+==+=====+===+=====+=====================+=====================+=====================+===========+===========+==+=====================+==+
|  | 338 | 2 | 337 | 2018-05-18 14:36:36 | 2018-05-18 14:36:36 | 2018-05-18 14:37:47 | COMPLETED | COMPLETED |  | 2018-05-18 14:37:47 |  |
+==+=====+===+=====+=====================+=====================+=====================+===========+===========+==+=====================+==+
|  | 339 | 2 | 338 | 2018-05-18 14:38:01 | 2018-05-18 14:38:01 | 2018-05-18 14:38:01 | COMPLETED | COMPLETED |  | 2018-05-18 14:38:01 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 340 | 2 | 339 | 2018-05-18 14:39:26 | 2018-05-18 14:39:26 | 2018-05-18 14:39:26 | COMPLETED | COMPLETED |  | 2018-05-18 14:39:26 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 341 | 2 | 340 | 2018-05-18 14:40:51 | 2018-05-18 14:40:51 | 2018-05-18 14:40:51 | COMPLETED | COMPLETED |  | 2018-05-18 14:40:51 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 342 | 2 | 341 | 2018-05-18 14:42:16 | 2018-05-18 14:42:16 | 2018-05-18 14:42:16 | COMPLETED | COMPLETED |  | 2018-05-18 14:42:16 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 343 | 2 | 342 | 2018-05-18 14:43:41 | 2018-05-18 14:43:41 | 2018-05-18 14:43:41 | COMPLETED | COMPLETED |  | 2018-05-18 14:43:41 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 344 | 2 | 343 | 2018-05-18 14:45:06 | 2018-05-18 14:45:06 | 2018-05-18 14:45:06 | COMPLETED | COMPLETED |  | 2018-05-18 14:45:06 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 345 | 2 | 344 | 2018-05-18 14:46:31 | 2018-05-18 14:46:31 | 2018-05-18 14:46:31 | COMPLETED | COMPLETED |  | 2018-05-18 14:46:31 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 346 | 2 | 345 | 2018-05-18 14:47:56 | 2018-05-18 14:47:56 | 2018-05-18 14:47:56 | COMPLETED | COMPLETED |  | 2018-05-18 14:47:56 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 347 | 2 | 346 | 2018-05-18 14:49:21 | 2018-05-18 14:49:21 | 2018-05-18 14:49:21 | COMPLETED | COMPLETED |  | 2018-05-18 14:49:21 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+
|  | 348 | 2 | 347 | 2018-05-18 14:50:46 | 2018-05-18 14:50:46 | 2018-05-18 14:50:46 | COMPLETED | COMPLETED |  | 2018-05-18 14:50:46 |  |
+--+-----+---+-----+---------------------+---------------------+---------------------+-----------+-----------+--+---------------------+--+

batch_step_execution

+==========================================================================================================================================================================================================================================================+
| STEP_EXECUTION_ID, VERSION, STEP_NAME, JOB_EXECUTION_ID, START_TIME, END_TIME, STATUS, COMMIT_COUNT, READ_COUNT, FILTER_COUNT, WRITE_COUNT, READ_SKIP_COUNT, WRITE_SKIP_COUNT, PROCESS_SKIP_COUNT, ROLLBACK_COUNT, EXIT_CODE, EXIT_MESSAGE, LAST_UPDATED |
+==========================================================================================================================================================================================================================================================+
| '338', '16', 'step1', '338', '2018-05-18 14:36:36', '2018-05-18 14:37:47', 'COMPLETED', '14', '132', '33', '99', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:37:47'                                                                              |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '339', '3', 'step1', '339', '2018-05-18 14:38:01', '2018-05-18 14:38:01', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:38:01'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '340', '3', 'step1', '340', '2018-05-18 14:39:26', '2018-05-18 14:39:26', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:39:26'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '341', '3', 'step1', '341', '2018-05-18 14:40:51', '2018-05-18 14:40:51', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:40:51'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '342', '3', 'step1', '342', '2018-05-18 14:42:16', '2018-05-18 14:42:16', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:42:16'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '343', '3', 'step1', '343', '2018-05-18 14:43:41', '2018-05-18 14:43:41', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:43:41'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '344', '3', 'step1', '344', '2018-05-18 14:45:06', '2018-05-18 14:45:06', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:45:06'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '345', '3', 'step1', '345', '2018-05-18 14:46:31', '2018-05-18 14:46:31', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:46:31'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '346', '3', 'step1', '346', '2018-05-18 14:47:56', '2018-05-18 14:47:56', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:47:56'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '347', '3', 'step1', '347', '2018-05-18 14:49:21', '2018-05-18 14:49:21', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:49:21'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '348', '3', 'step1', '348', '2018-05-18 14:50:46', '2018-05-18 14:50:46', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:50:46'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| '349', '3', 'step1', '349', '2018-05-18 14:52:11', '2018-05-18 14:52:11', 'COMPLETED', '1', '0', '0', '0', '0', '0', '0', '0', 'COMPLETED', '', '2018-05-18 14:52:11'                                                                                    |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Part of the console logs

BatchApplication - Started BatchApplication in 27.638 seconds (JVM running for 49.853) 13:30:04.905 [pool-11-thread-1] INFO org.springframework.batch.core.launch.support.SimpleJobLauncher - Job: [FlowJob: [name=importRegistrationJob]] launched with the following parameters: [{uniqueness=104422824800127}] 13:30:04.946
[pool-11-thread-1] INFO org.springframework.batch.core.job.SimpleStepHandler - Executing step: [step1] employeeData--> 13:31:14.002 [pool-11-thread-1] INFO
JobCompletionNotificationListener - !!! JOB FINISHED! Time to verify the results 13:31:14.015

[pool-11-thread-1] INFO org.springframework.batch.core.launch.support.SimpleJobLauncher - Job: [FlowJob: [name=importRegistrationJob]] completed with the following parameters: [{uniqueness=104507836733954}] and the following status: [COMPLETED] 13:31:29.766 [pool-11-thread-1] INFO
- Job finished with status :COMPLETED 13:32:54.713

[pool-11-thread-1] INFO org.springframework.batch.core.launch.support.SimpleJobLauncher - Job: [FlowJob: [name=importRegistrationJob]] launched with the following parameters: [{uniqueness=104592836710544}] 13:32:54.721
[pool-11-thread-1] INFO org.springframework.batch.core.job.SimpleStepHandler - Executing step: [step1] 13:32:54.750 [pool-11-thread-1] INFO batch.JobCompletionNotificationListener - !!! JOB FINISHED! Time to verify the results 13:32:54.750

[pool-11-thread-1] INFO org.springframework.batch.core.launch.support.SimpleJobLauncher - Job: [FlowJob: [name=importRegistrationJob]] launched with the following parameters: [{uniqueness=104677826302144}] 13:34:19.722
[pool-11-thread-1] INFO org.springframework.batch.core.job.SimpleStepHandler - Executing step: [step1]

1
springspring-batch
Tried solution in stackoverflow.com/questions/41361883/…, but no change – Nandhini
Problem seems to be around allowStartIfComplete(true) . Try running without it. You scheduler is working fine so problem is not as specified in above question. Also , please provide DB snapshots for JOB_EXECUTION & STEP_EXECUTION tables to have better idea as whats going on. – Sabir Khan
Added the batch_job_execution and batch_step_execution data. No luck even after removing allowStartIfComplete(true) – Nandhini
so do you have data to be read after first run ? STEP_EXECUTION_ID = 338 has columns COMMIT_COUNT , READ_COUNT etc non - zero values but later runs have these values as zero. Anyway, data in table again indicates that step and jobs both get kicked in but read count is zero so is that a correct case ? – Sabir Khan
Yes I am modifying the table so that is there is difference in the data from REST api, it would update the existing record to 'Cancelled' and add the new record. Its actually the same data from REST Api, it only changes once in few days – Nandhini

1 Answers

3
votes

It worked after I added @StepScope for reader, processor and writer

@Bean
    @StepScope
    ItemReader<EmployeeEmploymentDTO> restEmployeeReader(Environment environment, 
                                             RestTemplate restTemplate) {
        return new RESTEmployeeReader(
            environment.getRequiredProperty("rest.api.url"), 
            restTemplate
        );
    }

    @Bean
    @StepScope
    public RegistrationItemProcessor processor() {
        return new RegistrationItemProcessor();
    }

    @Bean
    @StepScope
    public ItemWriter<List<Registration>> writer() {
        return new MultiOutputItemWriter();
    }