Nerdy
Nerdy

Reputation: 192

Spring Batch job fails even though steps complete

I have a Spring Batch job with three steps. The first step runs through once, and the second and third steps run for each item in a queue. The code for the job:

return jobBuilderFactory.get("job")
        .incrementer(new RunIdIncrementer())
        .listener(jobListener())
        .flow(step1())
        .next(step2())
        .next(encrypt()).on("CONTINUE")
        .to(step2()).on("COMPLETED")
        .end().end().build();

The step execution listener for repeating the steps:

@AfterStep
@Override
public ExitStatus afterStep(StepExecution stepExecution) {
    if (queue.size() > 0) {
        return new ExitStatus("CONTINUE");
    } else {
        return new ExitStatus("COMPLETED");
    }
}

The queue is autowired in.

My problem is, even when the steps finish without an exit status of failed, the job still finishes with an exit status of failed.

I've already debugged it to see if the job fails because a step finishes with an exit status other than "COMPLETED", but that's not the case.

Any ideas? I'm thinking it might have to do with one of the steps not having a certain listener, but I don't know what that might be. I can put out more code if necessary. All help is appreciated.

Log Trace:

2017-05-18 10:08:10.327 [INFO ] c.d.r.r.BatchApplication - Starting BatchApplication on <computer_name> with PID <pid>
2017-05-18 10:08:10.329 [DEBUG] c.d.r.r.BatchApplication - Running with Spring Boot v1.4.1.RELEASE, Spring v4.3.3.RELEASE
2017-05-18 10:08:10.330 [INFO ] c.d.r.r.BatchApplication - The following profiles are active: <profile>
2017-05-18 10:08:10.367 [INFO ] o.s.c.a.AnnotationConfigApplicationContext - Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@163e4e87: startup date [Thu May 18 10:08:10 CDT 2017]; root of context hierarchy
2017-05-18 10:08:10.891 [WARN ] o.s.c.a.ConfigurationClassEnhancer - @Bean method ScopeConfiguration.stepScope is non-static and returns an object assignable to Spring's BeanFactoryPostProcessor interface. This will result in a failure to process annotations such as @Autowired, @Resource and @PostConstruct within the method's declaring @Configuration class. Add the 'static' modifier to this method to avoid these container lifecycle issues; see @Bean javadoc for complete details.
2017-05-18 10:08:10.899 [WARN ] o.s.c.a.ConfigurationClassEnhancer - @Bean method ScopeConfiguration.jobScope is non-static and returns an object assignable to Spring's BeanFactoryPostProcessor interface. This will result in a failure to process annotations such as @Autowired, @Resource and @PostConstruct within the method's declaring @Configuration class. Add the 'static' modifier to this method to avoid these container lifecycle issues; see @Bean javadoc for complete details.
2017-05-18 10:08:11.023 [INFO ] c.d.r.config.BaseBatchConfiguration - ****************************************************************************
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - **********  _____  __  __ _____     _____             __ _        **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** |  __ \|  \/  |  __ \   / ____|           / _(_)       **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** | |__) | \  / | |__) | | |     ___  _ __ | |_ _  __ _  **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** |  _  /| |\/| |  ___/  | |    / _ \| '_ \|  _| |/ _` | **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** | | \ \| |  | | |      | |___| (_) | | | | | | | (_| | **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** |_|  \_\_|  |_|_|       \_____\___/|_| |_|_| |_|\__, | **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - **********                                                  __/ | **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - **********                                                 |___/  **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** Property                     Value                     **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** ---------------------------  ------------------------- **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** this.profile                 <profile>                 **********
2017-05-18 10:08:11.024 [INFO ] c.d.r.config.BaseBatchConfiguration - ********** files.encrypted              false                     **********
2017-05-18 10:08:11.025 [INFO ] c.d.r.config.BaseBatchConfiguration - ****************************************************************************
2017-05-18 10:08:11.363 [INFO ] c.d.r.r.BatchApplication - Calling step1() for the job
2017-05-18 10:08:11.394 [INFO ] c.d.r.r.BatchApplication - Calling step2() for the job
2017-05-18 10:08:11.404 [INFO ] c.d.r.r.BatchApplication - Calling job() to begin the job
2017-05-18 10:08:11.553 [INFO ] o.s.b.a.b.JobLauncherCommandLineRunner - Running default command line with: [--spring.output.ansi.enabled=always, --spring.profiles.active=<profile>]
2017-05-18 10:08:11.772 [INFO ] o.s.b.c.r.s.JobRepositoryFactoryBean - No database type set, using meta data indicating: MYSQL
2017-05-18 10:08:11.857 [INFO ] o.s.b.c.l.support.SimpleJobLauncher - No TaskExecutor has been set, defaulting to synchronous executor.
2017-05-18 10:08:12.232 [INFO ] o.s.b.c.l.support.SimpleJobLauncher - Job: [FlowJob: [name=job]] launched with the following parameters: [{run.id=1, -spring.output.ansi.enabled=always, -spring.profiles.active=<profile>}]
2017-05-18 10:08:12.310 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:12.313 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                <APPLICATION_NAME>                                 *****
2017-05-18 10:08:12.313 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                       JOB job STARTING                                        *****
2017-05-18 10:08:12.313 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                            BEGIN JOB PARAMETERS                                            *****
2017-05-18 10:08:12.314 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Key:                                     Value:                                                            *****
2017-05-18 10:08:12.314 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** ---------------------------------------- ----------------------------------------------------------------- *****
2017-05-18 10:08:12.315 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** run.id                                   1                                                                 *****
2017-05-18 10:08:12.315 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** -spring.output.ansi.enabled              always                                                            *****
2017-05-18 10:08:12.315 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** -spring.profiles.active                  <profile>                                                               *****
2017-05-18 10:08:12.315 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:12.316 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:13.055 [INFO ] o.s.b.core.job.SimpleStepHandler - Executing step: [step1]
2017-05-18 10:08:13.201 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:13.202 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:13.202 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                STEP step1 STARTING                                *****
2017-05-18 10:08:13.203 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                           BEGIN STEP PARAMETERS                                            *****
2017-05-18 10:08:13.203 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:13.203 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:13.539 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:13.539 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:13.540 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                   Step step1 FINISHED with status of COMPLETED                    *****
2017-05-18 10:08:13.540 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records    Read:  2                                                                                        *****
2017-05-18 10:08:13.540 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records Written:  2                                                                                        *****
2017-05-18 10:08:13.540 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records Skipped:  0                                                                                        *****
2017-05-18 10:08:13.541 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:13.541 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:13.969 [INFO ] o.s.b.core.job.SimpleStepHandler - Executing step: [step2]
2017-05-18 10:08:14.025 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:14.026 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:14.026 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                      STEP step2 STARTING                                       *****
2017-05-18 10:08:14.026 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                           BEGIN STEP PARAMETERS                                            *****
2017-05-18 10:08:14.026 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:14.026 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:14.598 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:14.598 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:14.599 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                          Step step2 FINISHED with status of COMPLETED                          *****
2017-05-18 10:08:14.599 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records    Read:  3                                                                                        *****
2017-05-18 10:08:14.599 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records Written:  3                                                                                        *****
2017-05-18 10:08:14.599 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records Skipped:  0                                                                                        *****
2017-05-18 10:08:14.599 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:14.599 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:14.969 [INFO ] o.s.b.core.job.SimpleStepHandler - Executing step: [encrypt]
2017-05-18 10:08:15.101 [INFO ] c.d.r.encryption.EncryptionTasklet - Output file is: <output_file>
2017-05-18 10:08:15.101 [DEBUG] c.d.r.encryption.EncryptionTasklet - Configuration value for files.encrypted property: FALSE
2017-05-18 10:08:15.101 [INFO ] c.d.r.encryption.EncryptionTasklet - Output file is not to be Encrypted
2017-05-18 10:08:15.411 [INFO ] o.s.b.core.job.SimpleStepHandler - Duplicate step [step2] detected in execution of job=[job]. If either step fails, both will be executed again on restart.
2017-05-18 10:08:15.531 [INFO ] o.s.b.core.job.SimpleStepHandler - Executing step: [step2]
2017-05-18 10:08:15.580 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:15.580 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:15.580 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                      STEP step2 STARTING                                       *****
2017-05-18 10:08:15.580 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                           BEGIN STEP PARAMETERS                                            *****
2017-05-18 10:08:15.581 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:15.581 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:19.610 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:19.610 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:19.610 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                          Step step2 FINISHED with status of COMPLETED                          *****
2017-05-18 10:08:19.610 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records    Read:  3                                                                                        *****
2017-05-18 10:08:19.610 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records Written:  3                                                                                        *****
2017-05-18 10:08:19.610 [INFO ] c.d.rmp.listeners.SimpleJobListener - ***** Records Skipped:  0                                                                                        *****
2017-05-18 10:08:19.611 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:19.611 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:19.945 [INFO ] o.s.b.core.job.SimpleStepHandler - Duplicate step [encrypt] detected in execution of job=[job]. If either step fails, both will be executed again on restart.
2017-05-18 10:08:20.067 [INFO ] o.s.b.core.job.SimpleStepHandler - Executing step: [encrypt]
2017-05-18 10:08:20.209 [INFO ] c.d.r.encryption.EncryptionTasklet - Output file is: <output_file>
2017-05-18 10:08:20.210 [DEBUG] c.d.r.encryption.EncryptionTasklet - Configuration value for files.encrypted property: FALSE
2017-05-18 10:08:20.210 [INFO ] c.d.r.encryption.EncryptionTasklet - Output file is not to be Encrypted
2017-05-18 10:08:20.393 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:20.394 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                R E T U R N   M A I L   P R O C E S S I N G                                 *****
2017-05-18 10:08:20.394 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                            JOB job FINISHED with status of FAILED                             *****
2017-05-18 10:08:20.394 [INFO ] c.d.rmp.listeners.SimpleJobListener - *****                                                                                                            *****
2017-05-18 10:08:20.394 [INFO ] c.d.rmp.listeners.SimpleJobListener - **********************************************************************************************************************
2017-05-18 10:08:20.451 [INFO ] o.s.b.c.l.support.SimpleJobLauncher - Job: [FlowJob: [name=job]] completed with the following parameters: [{run.id=1, -spring.output.ansi.enabled=always, -spring.profiles.active=<profile>}] and the following status: [FAILED]
2017-05-18 10:08:20.453 [INFO ] c.d.r.r.BatchApplication - Started BatchApplication in 10.385 seconds (JVM running for 11.111)
2017-05-18 10:08:20.454 [INFO ] o.s.c.a.AnnotationConfigApplicationContext - Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@163e4e87: startup date [Thu May 18 10:08:10 CDT 2017]; root of context hierarchy

Sorry that the formatting isn't perfect, I had to change some names in there to make sure there wasn't any sensitive information.

Upvotes: 1

Views: 6210

Answers (2)

ayago
ayago

Reputation: 21

I know I am late but this might still help. If you are using a decider to control the flow instead of step exit status, you can do so as follows to properly end a job:

Flow syncStrategyFlow = new FlowBuilder<Flow>("syncStrategyFlow")
            .start(componentsHolder.syncFlowDecider) -- one of the decider is responsible for determining if flow should continue
                .on(SyncFlowDecider.CONTINUE)
                    .to(componentsHolder.deltaFilterTypeDecider) -- another decider, in this case its responsible for delegating task to specific step
                        .on(DeltaFilterTypeDecider.FILTER_TYPE_JOURNAL)
                            .to(componentsHolder.journalBasedSyncStep)
                            .next(componentsHolder.syncFlowDecider) --call continuation decider
                        .on(DeltaFilterTypeDecider.FILTER_TYPE_UPDATE_DATE)
                            .to(componentsHolder.updateDateBasedSyncStep)
                            .next(componentsHolder.syncFlowDecider) --call continuation decider
                        .on(DeltaFilterTypeDecider.FILTER_TYPE_HASH)
                            .to(componentsHolder.hashBasedSyncStep)
                            .next(componentsHolder.syncFlowDecider) --call continuation decider
                .on(SyncFlowDecider.COMPLETED)
                    .end()
            .build();

jobBuilderFactory.get("syncJob")
            .incrementer(new RunIdIncrementer())
            .start(syncStrategyFlow)
            .end()
            .build();

Upvotes: 0

Nerdy
Nerdy

Reputation: 192

After a lot of debugging and reading the documentation for Spring Batch, I found that if you want to repeat steps, you have to specify all of the steps to repeat in the job flow so the job will have a status of COMPLETED.

The job flow should look like this:

return jobBuilderFactory.get("job")
    .incrementer(new RunIdIncrementer())
    .listener(jobListener())
    .flow(step1())
    .next(step2())
    .next(encrypt()).on("CONTINUE")
    .to(step2())
    .next(encrypt()).on("COMPLETED")
    .end().end().build();

Upvotes: 6

Related Questions