Batch job instances not deleted when cleaning up task executions

[hpoettker]

Description:

When cleaning up task executions from the Data Flow dashboard, it occurs that the respective batch job instances are not deleted from the database although there are no more batch job executions linked to them.

This leads to launched tasks that fail with a NullPointerException.

The root cause is the query SQL_DELETE_BATCH_JOB_INSTANCE in JdbcDataflowJobExecutionDao. The column name JOB_INSTANCE_ID is used unqualified in the subquery although it should explicitly refer to the job instance table used in the outer query.

Release versions:

{
  "versionInfo": {
    "implementation": {
      "name": "spring-cloud-dataflow-server",
      "version": "2.6.3"
    },
    "core": {
      "name": "Spring Cloud Data Flow Core",
      "version": "2.6.3"
    },
    "dashboard": {
      "name": "Spring Cloud Dataflow UI",
      "version": "2.5.1"
    },
    "shell": {
      "name": "Spring Cloud Data Flow Shell",
      "version": "2.6.3",
      "url": "https://repo1.maven.org/maven2/org/springframework/cloud/spring-cloud-dataflow-shell/2.6.3/spring-cloud-dataflow-shell-2.6.3.jar"
    }
  },
  "featureInfo": {
    "streamsEnabled": false,
    "tasksEnabled": true,
    "schedulesEnabled": false,
    "grafanaEnabled": false
  },
  "securityInfo": {
    "isAuthenticationEnabled": false,
    "isAuthenticated": false,
    "username": null,
    "roles": []
  },
  "runtimeEnvironment": {
    "appDeployer": {
      "platformSpecificInfo": {},
      "deployerImplementationVersion": null,
      "deployerName": null,
      "deployerSpiVersion": null,
      "javaVersion": null,
      "platformApiVersion": null,
      "platformClientVersion": null,
      "platformHostVersion": null,
      "platformType": null,
      "springBootVersion": null,
      "springVersion": null
    },
    "taskLaunchers": [
      {
        "platformSpecificInfo": {},
        "deployerImplementationVersion": "2.4.1",
        "deployerName": "LocalTaskLauncher",
        "deployerSpiVersion": "2.4.1",
        "javaVersion": "1.8.0_192",
        "platformApiVersion": "Linux 5.8.16-2-MANJARO",
        "platformClientVersion": "5.8.16-2-MANJARO",
        "platformHostVersion": "5.8.16-2-MANJARO",
        "platformType": "Local",
        "springBootVersion": "2.2.8.RELEASE",
        "springVersion": "5.2.7.RELEASE"
      }
    ]
  },
  "grafanaInfo": {
    "url": "",
    "token": "",
    "refreshInterval": 15
  }
}

Custom apps:
Docker compose file

version: '3'

services:
  mysql:
    image: mysql:5.7.25
    container_name: dataflow-mysql
    ports:
      - "3306:3306"
    environment:
      MYSQL_DATABASE: dataflow
      MYSQL_USER: root
      MYSQL_ROOT_PASSWORD: rootpw
    expose:
      - 3306

  dataflow-server:
    image: springcloud/spring-cloud-dataflow-server:2.6.3
    container_name: dataflow-server
    ports:
      - "9393:9393"
    environment:
      - SPRING_DATASOURCE_URL=jdbc:mysql://mysql:3306/dataflow
      - SPRING_DATASOURCE_USERNAME=root
      - SPRING_DATASOURCE_PASSWORD=rootpw
      - SPRING_DATASOURCE_DRIVER_CLASS_NAME=org.mariadb.jdbc.Driver
      - SPRING_CLOUD_DATAFLOW_FEATURES_STREAMS_ENABLED=false
      - SPRING_CLOUD_DATAFLOW_FEATURES_SCHEDULES_ENABLED=false
      - SPRING_CLOUD_DATAFLOW_FEATURES_TASKS_ENABLED=true
      - SPRING_DATASOURCE_INITIALIZATION_MODE=always
    entrypoint: "./wait-for-it.sh mysql:3306 -- java -jar /maven/spring-cloud-dataflow-server.jar"
    volumes:
      - ${HOST_MOUNT_PATH:-.}:${DOCKER_MOUNT_PATH:-/root/scdf}
      - /var/run/docker.sock:/var/run/docker.sock

  app-import:
    image: springcloud/openjdk:2.0.0.RELEASE
    container_name: dataflow-app-import
    depends_on:
      - dataflow-server
    command: >
      /bin/sh -c "
        ./wait-for-it.sh -t 180 dataflow-server:9393;
        wget -qO- 'http://dataflow-server:9393/apps' --post-data='uri=${TASK_APPS_URI:-https://dataflow.spring.io/task-maven-latest&force=true}';
        echo 'Task apps imported'"

Steps to reproduce:

I could not reproduce the problem with a single task. But the following a bit more involved steps reproduce the problem consistently:

• docker-compose up to start the services in the docker compose file listed above
• open dashboard and execute the steps below
• create a task called composed-task with the definition timestamp && timestamp-batch
• create a task called duplicate-task with the definition one: timestamp && two: timestamp
• launch the task composed-task without further arguments/parameters
• launch the task duplicate-task without further arguments/parameters
• clean up task execution of composed-task
• launch the task composed-task without further arguments/parameters

The log of the task execution clean up contains the lines

dataflow-server    | 2020-11-03 07:59:20.149  INFO 1 --- [nio-9393-exec-4] o.s.c.d.s.s.i.DefaultTaskDeleteService   : Deleted the following Batch Job Execution related data for 3 Job Executions.
dataflow-server    | Batch Step Execution Context Rows: 4
dataflow-server    | Batch Step Executions Rows:        4
dataflow-server    | Batch Job Execution Context Rows:  3
dataflow-server    | Batch Job Execution Param Rows:    10
dataflow-server    | Batch Job Execution Rows:          3
dataflow-server    | Batch Job Instance Rows:           0.

The second launch of composed-task fails with a NullPointerException:

2020-11-03 07:59:40.888  INFO 242 --- [           main] o.s.c.d.c.ComposedTaskRunner             : No active profile set, falling back to default profiles: default
2020-11-03 07:59:41.570  INFO 242 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-11-03 07:59:41.572  INFO 242 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2020-11-03 07:59:41.600  INFO 242 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 17ms. Found 0 JPA repository interfaces.
2020-11-03 07:59:41.971  INFO 242 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.task.batch.configuration.TaskBatchAutoConfiguration' of type [org.springframework.cloud.task.batch.configuration.TaskBatchAutoConfiguration$$EnhancerBySpringCGLIB$$96d12f46] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-11-03 07:59:42.382  INFO 242 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2020-11-03 07:59:42.487  INFO 242 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2020-11-03 07:59:42.676  INFO 242 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2020-11-03 07:59:43.228  INFO 242 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 5.4.17.Final
2020-11-03 07:59:43.403  INFO 242 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.1.0.Final}
2020-11-03 07:59:43.922  INFO 242 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.MariaDB53Dialect
2020-11-03 07:59:44.383  INFO 242 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2020-11-03 07:59:44.401  INFO 242 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2020-11-03 07:59:44.525  INFO 242 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'taskExecutor'
2020-11-03 07:59:44.545  INFO 242 --- [           main] o.s.b.c.r.s.JobRepositoryFactoryBean     : No database type set, using meta data indicating: MYSQL
2020-11-03 07:59:44.561  INFO 242 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : No TaskExecutor has been set, defaulting to synchronous executor.
2020-11-03 07:59:45.023  INFO 242 --- [           main] o.s.c.d.c.ComposedTaskRunner             : Started ComposedTaskRunner in 4.773 seconds (JVM running for 5.442)
2020-11-03 07:59:45.024  INFO 242 --- [           main] o.s.b.a.b.JobLauncherCommandLineRunner   : Running default command line with: [--spring.cloud.data.flow.platformname=default, --spring.cloud.task.executionid=7, --spring.cloud.data.flow.taskappname=composed-task-runner]
2020-11-03 07:59:45.049  INFO 242 --- [           main] ConditionEvaluationReportLoggingListener : 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2020-11-03 07:59:45.055 ERROR 242 --- [           main] o.s.boot.SpringApplication               : Application run failed

java.lang.IllegalStateException: Failed to execute CommandLineRunner
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:787) [spring-boot-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:768) [spring-boot-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:322) [spring-boot-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1226) [spring-boot-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1215) [spring-boot-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.cloud.dataflow.composedtaskrunner.ComposedTaskRunner.main(ComposedTaskRunner.java:30) [classes!/:2.6.3]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_192]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_192]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_192]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_192]
	at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48) [spring-cloud-dataflow-composed-task-runner-2.6.3.jar:2.6.3]
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:87) [spring-cloud-dataflow-composed-task-runner-2.6.3.jar:2.6.3]
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:51) [spring-cloud-dataflow-composed-task-runner-2.6.3.jar:2.6.3]
	at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52) [spring-cloud-dataflow-composed-task-runner-2.6.3.jar:2.6.3]
Caused by: java.lang.NullPointerException: null
	at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.getExecutionContext(JdbcExecutionContextDao.java:111) ~[spring-batch-core-4.2.4.RELEASE.jar!/:4.2.4.RELEASE]
	at org.springframework.batch.core.repository.support.SimpleJobRepository.createJobExecution(SimpleJobRepository.java:136) ~[spring-batch-core-4.2.4.RELEASE.jar!/:4.2.4.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_192]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_192]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_192]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_192]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:367) ~[spring-tx-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:118) ~[spring-tx-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.batch.core.repository.support.AbstractJobRepositoryFactoryBean$1.invoke(AbstractJobRepositoryFactoryBean.java:181) ~[spring-batch-core-4.2.4.RELEASE.jar!/:4.2.4.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at com.sun.proxy.$Proxy65.createJobExecution(Unknown Source) ~[na:na]
	at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:137) ~[spring-batch-core-4.2.4.RELEASE.jar!/:4.2.4.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_192]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_192]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_192]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_192]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:127) ~[spring-batch-core-4.2.4.RELEASE.jar!/:4.2.4.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.7.RELEASE.jar!/:5.2.7.RELEASE]
	at com.sun.proxy.$Proxy67.run(Unknown Source) ~[na:na]
	at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.execute(JobLauncherCommandLineRunner.java:192) ~[spring-boot-autoconfigure-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.executeLocalJobs(JobLauncherCommandLineRunner.java:166) ~[spring-boot-autoconfigure-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.launchJobFromProperties(JobLauncherCommandLineRunner.java:153) ~[spring-boot-autoconfigure-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.run(JobLauncherCommandLineRunner.java:148) ~[spring-boot-autoconfigure-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:784) [spring-boot-2.2.8.RELEASE.jar!/:2.2.8.RELEASE]
	... 13 common frames omitted

2020-11-03 07:59:45.059  INFO 242 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'taskExecutor'
2020-11-03 07:59:45.059  INFO 242 --- [           main] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-11-03 07:59:45.062  INFO 242 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-11-03 07:59:45.065  INFO 242 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.