Spring batch process runs twice

Question

My Spring batch process runs twice.

After reading this link here, I added spring.batch.job.enabled=false to my application.yml. But the job itself did not run.

Then I tried doing some alterations to my job configuration Class. I moved the instance variables to method parameters hoping that would fix the issue. But no luck again.

Configuration Class

@Configuration
public class CarJobConfiguration {

    private static final Logger logger = LoggerFactory.getLogger(CarJobConfiguration.class);


    @Value("${com.car-update.thread-count}")
    private int threadCount;

    @Value("${com.car-update.delta-time}")
    private int deltaTime;




    @Bean
    public MongoItemReader<CarMongo> carReader( @Autowired MongoTemplate mongoTemplate, @Value("${com.car-update.chunkSize}") final int chuckSize) {
        MongoItemReader<CarMongo> reader = new MongoItemReader<>();
        reader.setTemplate(mongoTemplate);
        Map<String, Direction> sortDirection = new HashMap<>();
        sortDirection.put("_id", Direction.DESC);
        reader.setSort(sortDirection);
        reader.setTargetType(CarMongo.class);
        String query = getQuery();
        logger.info("***** Mongo query *****: {}", query);
        reader.setQuery(query);
        reader.setPageSize(chuckSize);
        return reader;
    }


    private String getQuery() {
        // Some logic to get query
    }


    @Bean
    public Job carDeltaJob(JobBuilderFactory jobBuilderFactory, JobCompletionNotificationListener listener, @Autowired @Qualifier("carDeltaStep")
             Step carDeltaStep) {
        return jobBuilderFactory.get("car_delta_extraction")
                .incrementer(new RunIdIncrementer())
                .listener(listener)
                .flow(carDeltaStep)
                .end()
                .build();
    }

    @Bean
    public Step carDeltaStep(StepBuilderFactory stepBuilderFactory, 
            @Value("${com.car-update.chunkSize}") final int chuckSize, 
            @Value("${com.car-update.thread-count}") final int threadCount,
            MongoItemReader<CarMongo> mongoItemReader, CarProcessor carProcessor, 
            CarWriter carWriter) {
        System.out.println("STEPSSSS this.chuckSize " + chuckSize +", thread count: " + this.threadCount);
        return stepBuilderFactory.get("car-delta-step")
                .<CarMongo, CarMongo>chunk(chuckSize)
                .reader(mongoItemReader)
                .processor(carProcessor)
                .writer(carWriter)
                .taskExecutor(taskExecutor())
                .throttleLimit(threadCount)
                .build();
    }

    @Bean
    public TaskExecutor taskExecutor(){
    //some logic
    }

}

AppConfig.java UPDATE

@Configuration
@EnableBatchProcessing(modular=true)
public class AppConfig {

    @Bean
    public ApplicationContextFactory SomeOtherExtractionJob() {
       return new GenericApplicationContextFactory(SomeOtherConfiguration.class);
    }


    @Bean
    public ApplicationContextFactory carDeltaJob() {
       return new GenericApplicationContextFactory(CarJobConfiguration.class);
    }
}

LOGS:

03:04:57.313  INFO 9092 --- [           main] c.w.ProductExtractionApplication         : Starting ProductExtractionApplication on CHMB113786.local with PID 9092 (/Users/andy/Car-Extractionbatch/bin/main started by andy in /Users/andy/Car-Extractionbatch)
03:04:57.318  INFO 9092 --- [           main] c.w.ProductExtractionApplication         : No active profile set, falling back to default profiles: default
03:04:57.353  INFO 9092 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@d78795: startup date [Thu Jun 06 03:04:57 IST 2019]; root of context hierarchy
03:04:57.774  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'catalogExtractionJob' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=appConfig; factoryMethodName=catalogExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/AppConfig.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=catalogExtractionJobConfiguration; factoryMethodName=catalogExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CatalogExtractionJobConfiguration.class]]
03:04:57.774  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'productCategoryExtractionJob' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=appConfig; factoryMethodName=productCategoryExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/AppConfig.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=categoryExtractionJobConfiguration; factoryMethodName=productCategoryExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CategoryExtractionJobConfiguration.class]]
03:04:57.775  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'taskExecutor' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=catalogExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CatalogExtractionJobConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=categoryExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CategoryExtractionJobConfiguration.class]]
03:04:57.775  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'dimensionExtractionJob' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=appConfig; factoryMethodName=dimensionExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/AppConfig.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=dimensionExtractionJobConfiguration; factoryMethodName=dimensionExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/DimensionExtractionJobConfiguration.class]]
03:04:57.776  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'taskExecutor' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=categoryExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CategoryExtractionJobConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=dimensionExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/DimensionExtractionJobConfiguration.class]]
03:04:57.776  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'gwpExtractionJob' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=appConfig; factoryMethodName=gwpExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/AppConfig.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=gwpExtractionJobConfiguration; factoryMethodName=gwpExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/GwpExtractionJobConfiguration.class]]
03:04:57.777  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'taskExecutor' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=dimensionExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/DimensionExtractionJobConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=gwpExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/GwpExtractionJobConfiguration.class]]
03:04:57.777  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'taskExecutor' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=gwpExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/GwpExtractionJobConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=carDeltaUpdateJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CarJobConfiguration.class]]
03:04:57.779  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'productRecommendedExtractionJob' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=appConfig; factoryMethodName=productRecommendedExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/AppConfig.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=productRecommendedExtractionJobConfiguration; factoryMethodName=productRecommendedExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/ProductRecommendedExtractionJobConfiguration.class]]
03:04:57.783  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'skuExtractionJob' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=appConfig; factoryMethodName=skuExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/AppConfig.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=skuExtractionJobConfiguration; factoryMethodName=skuExtractionJob; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/SkuExtractionJobConfiguration.class]]
03:04:57.783  INFO 9092 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'taskExecutor' with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=carDeltaUpdateJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/CarJobConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=skuExtractionJobConfiguration; factoryMethodName=taskExecutor; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/mycar/configuration/SkuExtractionJobConfiguration.class]]
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.springframework.cglib.core.ReflectUtils$1 (file:/Users/andy/.gradle/caches/modules-2/files-2.1/org.springframework/spring-core/5.0.5.RELEASE/1bd9feb1d9dac6accd27f5244b6c47cfcb55045c/spring-core-5.0.5.RELEASE.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of org.springframework.cglib.core.ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
03:04:58.414  INFO 9092 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
03:04:58.490  INFO 9092 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
03:04:58.500  INFO 9092 --- [           main] o.s.b.c.r.s.JobRepositoryFactoryBean     : No database type set, using meta data indicating: H2
03:04:58.623  INFO 9092 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : No TaskExecutor has been set, defaulting to synchronous executor.
03:04:58.878  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Cluster created with settings {hosts=[mongo1:27017, mongo2:27017, mongo3:27017], mode=MULTIPLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
03:04:58.879  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Adding discovered server mongo1:27017 to client view of cluster
03:04:58.924  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Adding discovered server mongo2:27017 to client view of cluster
03:04:58.927  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Adding discovered server mongo3:27017 to client view of cluster
03:04:59.051  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Cluster created with settings {hosts=[mongo1:27017, mongo2:27017, mongo3:27017], mode=MULTIPLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
03:04:59.052  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Adding discovered server mongo1:27017 to client view of cluster
03:04:59.054  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Adding discovered server mongo2:27017 to client view of cluster
03:04:59.056  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Adding discovered server mongo3:27017 to client view of cluster
#####from Inside JobCompletionNotificationListener construtor#####
03:04:59.193  INFO 9092 --- [           main] org.mongodb.driver.cluster               : Cluster description not yet available. Waiting for 30000 ms before timing out
03:05:01.912  INFO 9092 --- [reens.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:2, serverValue:816666}] to mongo2:27017
03:05:01.912  INFO 9092 --- [reens.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:5, serverValue:816667}] to mongo2:27017
03:05:01.914  INFO 9092 --- [reens.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:4, serverValue:510177}] to mongo1:27017
03:05:01.914  INFO 9092 --- [reens.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:1, serverValue:510176}] to mongo1:27017
03:05:01.916  INFO 9092 --- [reens.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:6, serverValue:1677186}] to mongo3:27017
03:05:02.206  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mongo1:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 6, 7]}, minWireVersion=0, maxWireVersion=6, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=288249712, setName='mongodbEnterprise_lowerEnvironment', canonicalAddress=mongo1:27017, hosts=[mongo2:27017, mongo3:27017, mongo1:27017], passives=[], arbiters=[], primary='mongo1:27017', tagSet=TagSet{[]}, electionId=7fffffff0000000000000127, setVersion=2, lastWriteDate=Thu Jun 06 03:05:05 IST 2019, lastUpdateTimeNanos=368580308198796}
03:05:02.207  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mongo3:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 6, 7]}, minWireVersion=0, maxWireVersion=6, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=290187882, setName='mongodbEnterprise_lowerEnvironment', canonicalAddress=mongo3:27017, hosts=[mongo2:27017, mongo3:27017, mongo1:27017], passives=[], arbiters=[], primary='mongo1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Thu Jun 06 03:05:05 IST 2019, lastUpdateTimeNanos=368580309720591}
03:05:02.207  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mongo2:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 6, 7]}, minWireVersion=0, maxWireVersion=6, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=288378005, setName='mongodbEnterprise_lowerEnvironment', canonicalAddress=mongo2:27017, hosts=[mongo2:27017, mongo3:27017, mongo1:27017], passives=[], arbiters=[], primary='mongo1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Thu Jun 06 03:05:05 IST 2019, lastUpdateTimeNanos=368580309928421}
03:05:02.206  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mongo1:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 6, 7]}, minWireVersion=0, maxWireVersion=6, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=286870787, setName='mongodbEnterprise_lowerEnvironment', canonicalAddress=mongo1:27017, hosts=[mongo2:27017, mongo3:27017, mongo1:27017], passives=[], arbiters=[], primary='mongo1:27017', tagSet=TagSet{[]}, electionId=7fffffff0000000000000127, setVersion=2, lastWriteDate=Thu Jun 06 03:05:05 IST 2019, lastUpdateTimeNanos=368580308253613}
03:05:02.209  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Discovered cluster type of REPLICA_SET
03:05:02.210  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Setting max election id to 7fffffff0000000000000127 from replica set primary mongo1:27017
03:05:02.210  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Discovered cluster type of REPLICA_SET
03:05:02.210  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Setting max set version to 2 from replica set primary mongo1:27017
03:05:02.211  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Setting max election id to 7fffffff0000000000000127 from replica set primary mongo1:27017
03:05:02.211  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Discovered replica set primary mongo1:27017
03:05:02.212  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Setting max set version to 2 from replica set primary mongo1:27017
03:05:02.213  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Discovered replica set primary mongo1:27017
03:05:02.216  INFO 9092 --- [reens.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:3, serverValue:1677187}] to mongo3:27017
03:05:02.218  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mongo2:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 6, 7]}, minWireVersion=0, maxWireVersion=6, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=301879122, setName='mongodbEnterprise_lowerEnvironment', canonicalAddress=mongo2:27017, hosts=[mongo2:27017, mongo3:27017, mongo1:27017], passives=[], arbiters=[], primary='mongo1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Thu Jun 06 03:05:05 IST 2019, lastUpdateTimeNanos=368580320523441}
03:05:02.487  INFO 9092 --- [reens.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mongo3:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 6, 7]}, minWireVersion=0, maxWireVersion=6, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=269161222, setName='mongodbEnterprise_lowerEnvironment', canonicalAddress=mongo3:27017, hosts=[mongo2:27017, mongo3:27017, mongo1:27017], passives=[], arbiters=[], primary='mongo1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Thu Jun 06 03:05:06 IST 2019, lastUpdateTimeNanos=368580589179359}
03:05:04.645  INFO 9092 --- [           main] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:7, serverValue:510178}] to mongo1:27017
03:09:05.799  WARN 9092 --- [           main] o.s.b.c.s.b.FaultTolerantStepBuilder     : Asynchronous TaskExecutor detected with ItemStream reader.  This is probably an error, and may lead to incorrect restart data being stored.
***** Mongo query *****: {'dttm' : { $gte: ISODate('2019-06-06T02:39:06.434209Z')}}
STEPSSSS this.chuckSize 1000, thread count: 10
03:09:06.575  INFO 9092 --- [           main] o.s.jdbc.datasource.init.ScriptUtils     : Executing SQL script from class path resource [org/springframework/batch/core/schema-h2.sql]
03:09:06.614  INFO 9092 --- [           main] o.s.jdbc.datasource.init.ScriptUtils     : Executed SQL script from class path resource [org/springframework/batch/core/schema-h2.sql] in 38 ms.
03:09:06.976  INFO 9092 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
03:09:06.980  INFO 9092 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Bean with name 'batchDataSource' has been autodetected for JMX exposure
03:09:06.981  INFO 9092 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Bean with name 'mariaDB' has been autodetected for JMX exposure
03:09:06.986  INFO 9092 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Located MBean 'mariaDB': registering with JMX server as MBean [com.zaxxer.hikari:name=mariaDB,type=HikariDataSource]
03:09:06.988  INFO 9092 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Located MBean 'batchDataSource': registering with JMX server as MBean [com.zaxxer.hikari:name=batchDataSource,type=HikariDataSource]
03:09:06.992  INFO 9092 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase -2147482648
03:09:06.995  INFO 9092 --- [           main] ory$ResourceAnnotationApplicationContext : Refreshing ResourceAnnotationApplicationContext:com.mycar.configuration.CarJobConfiguration
***** Mongo query *****: {'dttm' : { $gte: ISODate('2019-06-06T02:39:07.00335Z')}}
STEPSSSS this.chuckSize 1000, thread count: 10
03:09:07.095  INFO 9092 --- [           main] c.w.ProductExtractionApplication         : Started CarExtractionApplication in 250.186 seconds (JVM running for 251.358)
03:09:07.097  INFO 9092 --- [           main] o.s.b.a.b.JobLauncherCommandLineRunner   : Running default command line with: [--spring.output.ansi.enabled=always]
03:09:07.141  INFO 9092 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=car_delta_extraction]] launched with the following parameters: [{-spring.output.ansi.enabled=always, run.id=1}]
03:09:07.159  INFO 9092 --- [           main] o.s.batch.core.job.SimpleStepHandler     : Executing step: [car-delta-step]
********** Processor **********
********** Processor **********
03:09:26.017  INFO 9092 --- [           main] c.w.l.JobCompletionNotificationListener  : !!! JOB FINISHED! Time to verify the results  : 18 seconds
03:09:26.019  INFO 9092 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=car_delta_extraction]] completed with the following parameters: [{-spring.output.ansi.enabled=always, run.id=1}] and the following status: [COMPLETED]
03:09:26.066  INFO 9092 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=car_delta_extraction]] launched with the following parameters: [{-spring.output.ansi.enabled=always, run.id=2}]
03:09:26.073  INFO 9092 --- [           main] o.s.batch.core.job.SimpleStepHandler     : Executing step: [car-delta-step]
********** Processor **********
********** Processor **********
03:09:31.753  INFO 9092 --- [           main] c.w.l.JobCompletionNotificationListener  : !!! JOB FINISHED! Time to verify the results  : 5 seconds
03:09:31.755  INFO 9092 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=car_delta_extraction]] completed with the following parameters: [{-spring.output.ansi.enabled=always, run.id=2}] and the following status: [COMPLETED]
03:09:31.757  INFO 9092 --- [       Thread-1] s.c.a.AnnotationConfigApplicationContext : Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@d78795: startup date [Thu Jun 06 03:04:57 IST 2019]; root of context hierarchy
03:09:31.759  INFO 9092 --- [       Thread-1] o.s.c.support.DefaultLifecycleProcessor  : Stopping beans in phase -2147482648
03:09:31.760  INFO 9092 --- [       Thread-1] ory$ResourceAnnotationApplicationContext : Closing ResourceAnnotationApplicationContext:com.mycar.configuration.CarJobConfiguration
03:09:31.766  INFO 9092 --- [       Thread-1] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown
03:09:31.767  INFO 9092 --- [       Thread-1] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans
03:09:32.042  INFO 9092 --- [       Thread-1] org.mongodb.driver.connection            : Closed connection [connectionId{localValue:7, serverValue:510178}] to mongo1:27017 because the pool has been closed.
03:09:32.043  INFO 9092 --- [       Thread-1] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
03:09:32.048  INFO 9092 --- [       Thread-1] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

From the Logs, you can notice that

*********** Processor *********** is printed twice.(Processor is printed twice each time as there are 2 records only)
Mongo Query and the chunck size and threadcount are printed twice.
!!! JOB FINISHED! Time to verify the results : __ is printed twice

Any suggestion would be greatly helpful.

Have you configured `CarJobConfiguration` in a child `ApplicationContext`? — Philip Wrage, Jun 07 '19 at 03:02
@PhilipWrage: Thanks for the comment. Yes, I have configured. I have updated the post with AppConfig.java. The issue got fixed after I had the **same *name* carDeltaJob()** in both **AppConfig.java** and **CarJobConfiguration.java** I am not able to figure out the actual reason although it is working fine now. Can you please help me out? — Andy, Jun 08 '19 at 19:19

score 1 · Answer 1 · answered Nov 27 '19 at 01:09

I had this happen recently for a Job created in the method runScenario(). In my Spring Boot App, I had this:

@SpringBootApplication
public class SimulationBatchServiceApplication implements CommandLineRunner {

  @Autowired
  private JobLauncher jobLauncher;

  @Autowired
  private Job job;

  public static void main(String[] args) {
    SpringApplication.run(SimulationBatchServiceApplication.class, args);
  }

  @Override
  public void run(String... args) throws Exception {
      JobParameters params = new JobParametersBuilder()
            .addString("runScenario", String.valueOf(System.currentTimeMillis()))
            .toJobParameters();
      jobLauncher.run(job, params);
  }
}

runScenario() was also marked with @Bean. Spring therefore picked it up twice -- once to @Autowire the job field, once because I specified "runScenario" in JobParameters. Removing "runScenario" from the JobParameters object did the trick.

@Override
public void run(String... args) throws Exception {
    jobLauncher.run(job, new JobParameters());
}

If I required a more dynamic case, I believe I could have removed @Bean and the job field, then specified "runScenario" in JobParameters. That way no autowiring would've occurred, but the job would've been found anyway by looking for the method name.

Perhaps this isn't your issue, but hopefully it provides a clue (or helps a future reader!)

Spring batch process runs twice

1 Answers1