control-service: The logs when deploying a job are full of errors even when everything is going good #2199
Description
What is the feature request? What problem does it solve?
A teammate reported issues with quickstart VDK in this ticket: #2176.
In the ticket they included the logs of control service because they assumed that they were relevant to the issue they were experiencing.
However these errors appear in the logs even when a deployment is successful.
Included below is the entire logs of the control service.
So why do these errors appear even in a successful deployment?
When a job gets deployed we first check if there is an image for that job if there is not then we build the image first and then deploy.
While the image is building we actuall ping the k8s cluster to see does the cronjob exist even though we know it shouldn't.
Suggested solution
Don't check for the cronjob till we know that the image build is complete.
ikoleva@ikoleva2MD6R /tmp % kubectl logs -f service/vdk-svc
15:27:44.478 [main] INFO com.vmware.taurus.ControlplaneApplication - Starting ControlplaneApplication with args:
15:27:44.498 [main] DEBUG com.vmware.taurus.ControlplaneApplication - Environment variables:
AUTHORITIES_CLAIM_NAME: perms,
AUTHORIZED_CUSTOM_CLAIM_VALUES: ,
AUTHORIZED_ROLES: ,
AWS_ACCESS_KEY_ID: ,
AWS_ACCESS_KEY_SECRET: ,
AWS_REGION: ,
CREDENTIALS_PRINCIPAL_PATTERN: pa__view_%(data_job),
CREDENTIALS_REPOSITORY: EMPTY,
CUSTOM_CLAIM_NAME: context_name,
DATAJOBS_AUTHORIZATION_JWT_CLAIM_USERNAME: username,
DATAJOBS_AUTHORIZATION_WEBHOOK_ENDPOINT: ,
DATAJOBS_AWS_ASSUME_IAM_ROLE: false,
DATAJOBS_AWS_DEFAULT_SESSION_DURATION_SECONDS: 1800,
DATAJOBS_AWS_ROLE_ARN: ,
DATAJOBS_AWS_SERVICE_ACCOUNT_ACCESS_KEY_ID: ,
DATAJOBS_AWS_SERVICE_ACCOUNT_SECRET_ACCESS_KEY: ,
DATAJOBS_BUILDER_IMAGE: registry.hub.docker.com/versatiledatakit/job-builder:1.2.3,
DATAJOBS_CONTROL_K8S_NAMESPACE: ,
DATAJOBS_DEPLOYMENT_BUILDER_EXTRAARGS: --insecure,
DATAJOBS_DEPLOYMENT_BUILDER_SECURITY_CONTEXT_FS_GROUP: 1000,
DATAJOBS_DEPLOYMENT_BUILDER_SECURITY_CONTEXT_RUN_AS_GROUP: 1000,
DATAJOBS_DEPLOYMENT_BUILDER_SECURITY_CONTEXT_RUN_AS_USER: 0,
DATAJOBS_DEPLOYMENT_DEFAULT_PYTHON_VERSION: 3.9,
DATAJOBS_DEPLOYMENT_INITCONTAINER_RESOURCES_LIMITS_CPU: 500m,
DATAJOBS_DEPLOYMENT_INITCONTAINER_RESOURCES_LIMITS_MEMORY: 500Mi,
DATAJOBS_DEPLOYMENT_INITCONTAINER_RESOURCES_REQUESTS_CPU: 100m,
DATAJOBS_DEPLOYMENT_INITCONTAINER_RESOURCES_REQUESTS_MEMORY: 100Mi,
DATAJOBS_DEPLOYMENT_SUPPORTED_PYTHON_VERSIONS: {"3.9":{"baseImage":"registry.hub.docker.com/versatiledatakit/data-job-base-python-3.9:latest","vdkImage":"registry.hub.docker.com/versatiledatakit/quickstart-vdk:release"}},
DATAJOBS_EXECUTIONS_LOGS_URL_DATE_FORMAT: unix,
DATAJOBS_EXECUTIONS_LOGS_URL_DATE_TEMPLATE: http://localhost:8092/data-jobs/for-team/{{team_name}}/jobs/{{job_name}}/executions/{{execution_id}}/logs?tail_lines=400,
DATAJOBS_EXECUTION_MAXIMUM_EXECUTIONS_TO_STORE: 100,
DATAJOBS_EXECUTION_TTL_SECONDS: 1209600,
DATAJOBS_GIT_COMMIT_HASH: 5f078fe,
DATAJOBS_POST_CREATE_WEBHOOK_ENDPOINT: ,
DATAJOBS_POST_CREATE_WEBHOOK_INTERNAL_ERRORS_RETRIES: 3,
DATAJOBS_POST_DELETE_WEBHOOK_ENDPOINT: ,
DATAJOBS_POST_DELETE_WEBHOOK_INTERNAL_ERRORS_RETRIES: 3,
DATAJOBS_TEMP_STORAGE_FOLDER: /datajobs_temp_storage,
DB_JDBC_URL: jdbc:postgresql://vdk-cockroachdb-public:26257/defaultdb?sslmode=disable,
DB_PASSWORD: ,
DB_USERNAME: root,
DEFAULT_BUILDER_RESOURCES_LIMITS_CPU: 0,
DEFAULT_BUILDER_RESOURCES_LIMITS_MEMORY: 0,
DEFAULT_BUILDER_RESOURCES_REQUESTS_CPU: 0,
DEFAULT_BUILDER_RESOURCES_REQUESTS_MEMORY: 0,
DEFAULT_JOB_RESOURCES_LIMITS_CPU: 0,
DEFAULT_JOB_RESOURCES_LIMITS_MEMORY: 0,
DEFAULT_JOB_RESOURCES_REQUESTS_CPU: 0,
DEFAULT_JOB_RESOURCES_REQUESTS_MEMORY: 0,
DEFAULT_MONITORING_INITIAL_DELAY_SYNC_INTERVAL: 10000,
DEFAULT_MONITORING_SYNC_INTERVAL: 60000,
DEPLOYMENT_K8S_KUBECONFIG: /etc/secrets/deployment-kubeconfig,
DEPLOYMENT_K8S_NAMESPACE: ,
DOCKER_REGISTRY_PASSWORD: ,
DOCKER_REGISTRY_TYPE: generic,
DOCKER_REGISTRY_USERNAME: ,
DOCKER_REPOSITORY_URL: vdk-docker-registry:5000,
EXTRA_ARGUMENTS: ,
EXTRA_JAVA_OPTS: ,
FEATUREFLAG_AUTHORIZATION_ENABLED: false,
FEATUREFLAG_SECURITY_ENABLED: false,
GIT_BRANCH: master,
GIT_PASSWORD: vdkpass,
GIT_PASSWORD_READ_WRITE: vdkpass,
GIT_REMOTE: origin,
GIT_SSL_ENABLED: false,
GIT_URL: 172.18.0.4/vdkuser/vdk-git-repo.git,
GIT_USERNAME: vdkuser,
GIT_USERNAME_READ_WRITE: vdkuser,
HOME: /root,
HOSTNAME: vdk-dep-6d549b4cbc-x2pcr,
IMAGE_NAME: registry.hub.docker.com/versatiledatakit/pipelines-control-service:5f078fe,
JAVA_HOME: /opt/java/openjdk,
JAVA_VERSION: jdk-17.0.7+7,
KADMIN_PASSWORD: ,
KADMIN_USER: ,
KRB5_CONFIG: /etc/secrets/krb5.conf,
KUBERNETES_PORT: tcp://10.96.0.1:443,
KUBERNETES_PORT_443_TCP: tcp://10.96.0.1:443,
KUBERNETES_PORT_443_TCP_ADDR: 10.96.0.1,
KUBERNETES_PORT_443_TCP_PORT: 443,
KUBERNETES_PORT_443_TCP_PROTO: tcp,
KUBERNETES_SERVICE_HOST: 10.96.0.1,
KUBERNETES_SERVICE_PORT: 443,
KUBERNETES_SERVICE_PORT_HTTPS: 443,
LANG: en_US.UTF-8,
LANGUAGE: en_US:en,
LC_ALL: en_US.UTF-8,
NOTIFICATION_CC_EMAILS: ,
NOTIFICATION_OWNER_EMAIL: taurus@vmware.com,
NOTIFICATION_OWNER_NAME: Versatile Data Kit,
PATH: /opt/java/openjdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin,
PROXY_DOCKER_REPO_URL: localhost:5000,
PWD: /application,
SERVER_MAX_HTTP_HEADER_SIZE: 8KB,
SPRING_PROFILE: prod,
SPRING_SECURITY_OAUTH2_RESOURCESERVER_JWT_ISSUER_URI: ,
SPRING_SECURITY_OAUTH2_RESOURCESERVER_JWT_JWK_SET_URI: http://localhost,
UPLOAD_VALIDATION_FILETYPES_ALLOWLIST: ,
VDK_COCKROACHDB_PUBLIC_PORT: tcp://10.96.152.89:26257,
VDK_COCKROACHDB_PUBLIC_PORT_26257_TCP: tcp://10.96.152.89:26257,
VDK_COCKROACHDB_PUBLIC_PORT_26257_TCP_ADDR: 10.96.152.89,
VDK_COCKROACHDB_PUBLIC_PORT_26257_TCP_PORT: 26257,
VDK_COCKROACHDB_PUBLIC_PORT_26257_TCP_PROTO: tcp,
VDK_COCKROACHDB_PUBLIC_PORT_8080_TCP: tcp://10.96.152.89:8080,
VDK_COCKROACHDB_PUBLIC_PORT_8080_TCP_ADDR: 10.96.152.89,
VDK_COCKROACHDB_PUBLIC_PORT_8080_TCP_PORT: 8080,
VDK_COCKROACHDB_PUBLIC_PORT_8080_TCP_PROTO: tcp,
VDK_COCKROACHDB_PUBLIC_SERVICE_HOST: 10.96.152.89,
VDK_COCKROACHDB_PUBLIC_SERVICE_PORT: 26257,
VDK_COCKROACHDB_PUBLIC_SERVICE_PORT_GRPC: 26257,
VDK_COCKROACHDB_PUBLIC_SERVICE_PORT_HTTP: 8080,
VDK_OPTIONS_INI: /etc/secrets/vdk-options.ini,
VDK_SVC_PORT: tcp://10.96.99.151:8092,
VDK_SVC_PORT_8092_TCP: tcp://10.96.99.151:8092,
VDK_SVC_PORT_8092_TCP_ADDR: 10.96.99.151,
VDK_SVC_PORT_8092_TCP_PORT: 8092,
VDK_SVC_PORT_8092_TCP_PROTO: tcp,
VDK_SVC_SERVICE_HOST: 10.96.99.151,
VDK_SVC_SERVICE_PORT: 8092,
VDK_SVC_SERVICE_PORT_HTTP: 8092,
VDK_UI_PORT: tcp://10.96.211.187:80,
VDK_UI_PORT_80_TCP: tcp://10.96.211.187:80,
VDK_UI_PORT_80_TCP_ADDR: 10.96.211.187,
VDK_UI_PORT_80_TCP_PORT: 80,
VDK_UI_PORT_80_TCP_PROTO: tcp,
VDK_UI_SERVICE_HOST: 10.96.211.187,
VDK_UI_SERVICE_PORT: 80,
datajobs_version: 1.6.884364555,
telemetry_ph_environment: production
15:27:44.499 [main] DEBUG com.vmware.taurus.ControlplaneApplication - Java properties:
file.encoding: UTF-8,
file.separator: /,
java.class.path: .,
java.class.version: 61.0,
java.home: /opt/java/openjdk,
java.io.tmpdir: /tmp,
java.library.path: /usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib,
java.runtime.name: OpenJDK Runtime Environment,
java.runtime.version: 17.0.7+7,
java.specification.name: Java Platform API Specification,
java.specification.vendor: Oracle Corporation,
java.specification.version: 17,
java.vendor.url.bug: https://github.com/adoptium/adoptium-support/issues,
java.vendor.url: https://adoptium.net/,
java.vendor.version: Temurin-17.0.7+7,
java.vendor: Eclipse Adoptium,
java.version.date: 2023-04-18,
java.version: 17.0.7,
java.vm.compressedOopsMode: 32-bit,
java.vm.info: mixed mode, sharing,
java.vm.name: OpenJDK 64-Bit Server VM,
java.vm.specification.name: Java Virtual Machine Specification,
java.vm.specification.vendor: Oracle Corporation,
java.vm.specification.version: 17,
java.vm.vendor: Eclipse Adoptium,
java.vm.version: 17.0.7+7,
jdk.debug: release,
line.separator:
,
native.encoding: UTF-8,
os.arch: amd64,
os.name: Linux,
os.version: 5.15.49-linuxkit,
path.separator: :,
spring.profiles.active: prod,
sun.arch.data.model: 64,
sun.boot.library.path: /opt/java/openjdk/lib,
sun.cpu.endian: little,
sun.io.unicode.encoding: UnicodeLittle,
sun.java.command: org.springframework.boot.loader.JarLauncher,
sun.java.launcher: SUN_STANDARD,
sun.jnu.encoding: UTF-8,
sun.management.compiler: HotSpot 64-Bit Tiered Compilers,
sun.security.krb5.debug: true,
user.country: US,
user.dir: /application,
user.home: /root,
user.language: en,
user.name: root,
user.timezone: Etc/UTC
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.7.12)
2023-05-31 15:27:45,243 INFO [OpId:] nd-preinit o.h.v.internal.util.Version HV000001: Hibernate Validator 6.2.5.Final
2023-05-31 15:27:45,279 INFO [OpId:] main c.v.t.ControlplaneApplication Starting ControlplaneApplication using Java 17.0.7 on vdk-dep-6d549b4cbc-x2pcr with PID 10 (/application/BOOT-INF/lib/base-0.1.78-SNAPSHOT-plain.jar started by root in /application)
2023-05-31 15:27:45,280 INFO [OpId:] main c.v.t.ControlplaneApplication The following 1 profile is active: "prod"
2023-05-31 15:27:46,571 INFO [OpId:] main .RepositoryConfigurationDelegate Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2023-05-31 15:27:46,692 INFO [OpId:] main .RepositoryConfigurationDelegate Finished Spring Data repository scanning in 112 ms. Found 3 JPA repository interfaces.
2023-05-31 15:27:46,954 INFO [OpId:] main elegate$BeanPostProcessorChecker Bean 'repositoryRetryOperationsConfiguration' of type [com.vmware.taurus.service.RepositoryRetryOperationsConfiguration$$EnhancerBySpringCGLIB$$9550fd26] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2023-05-31 15:27:47,520 INFO [OpId:] main o.s.b.w.e.tomcat.TomcatWebServer Tomcat initialized with port(s): 8092 (http)
2023-05-31 15:27:47,529 INFO [OpId:] main o.a.c.http11.Http11NioProtocol Initializing ProtocolHandler ["http-nio-8092"]
2023-05-31 15:27:47,530 INFO [OpId:] main o.a.c.core.StandardService Starting service [Tomcat]
2023-05-31 15:27:47,530 INFO [OpId:] main o.a.catalina.core.StandardEngine Starting Servlet engine: [Apache Tomcat/9.0.75]
2023-05-31 15:27:47,602 INFO [OpId:] main o.a.c.c.C.[.[localhost].[/] Initializing Spring embedded WebApplicationContext
2023-05-31 15:27:47,602 INFO [OpId:] main rvletWebServerApplicationContext Root WebApplicationContext: initialization completed in 2278 ms
2023-05-31 15:27:48,071 INFO [OpId:] main c.v.t.s.diag.telemetry.Telemetry Telemetry endpoint is empty and sending telemetry is skipped
2023-05-31 15:27:48,262 INFO [OpId:] main o.f.c.i.license.VersionPrinter Flyway Community Edition 8.5.13 by Redgate
2023-05-31 15:27:48,263 INFO [OpId:] main o.f.c.i.license.VersionPrinter See what's new here: https://flywaydb.org/documentation/learnmore/releaseNotes#8.5.13
2023-05-31 15:27:48,263 INFO [OpId:] main o.f.c.i.license.VersionPrinter
2023-05-31 15:27:48,273 INFO [OpId:] main c.zaxxer.hikari.HikariDataSource HikariPool-1 - Starting...
2023-05-31 15:27:48,358 INFO [OpId:] main c.zaxxer.hikari.HikariDataSource HikariPool-1 - Start completed.
2023-05-31 15:27:48,372 INFO [OpId:] main o.f.c.i.d.base.BaseDatabaseType Database: jdbc:postgresql://vdk-cockroachdb-public:26257/defaultdb (PostgreSQL 9.5)
2023-05-31 15:27:48,408 INFO [OpId:] main o.f.c.i.command.DbValidate Successfully validated 16 migrations (execution time 00:00.016s)
2023-05-31 15:27:48,419 INFO [OpId:] main o.f.c.i.s.JdbcTableSchemaHistory Creating Schema History table "defaultdb"."flyway_schema_history" ...
2023-05-31 15:27:48,790 INFO [OpId:] main o.f.c.internal.command.DbMigrate Current version of schema "defaultdb": << Empty Schema >>
2023-05-31 15:27:48,794 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20200403104016 - create table data job" [non-transactional]
2023-05-31 15:27:48,926 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20201205103200 - add column default db type table data job" [non-transactional]
2023-05-31 15:27:49,145 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20202105114500 - add generate keytab table data job" [non-transactional]
2023-05-31 15:27:49,348 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20202411154500 - add latest job deployment status data job" [non-transactional]
2023-05-31 15:27:49,532 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20211903160000 - add latest job termination status data job" [non-transactional]
2023-05-31 15:27:49,742 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20212004120000 - add latest job execution id data job" [non-transactional]
2023-05-31 15:27:49,935 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20212904120000 - add enable execution notifications" [non-transactional]
2023-05-31 15:27:50,153 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213006154500 - create table data job execution" [non-transactional]
2023-05-31 15:27:50,353 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213106120000 - add notification delay period minutes" [non-transactional]
2023-05-31 15:27:50,642 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213107120000 - create table job properties" [non-transactional]
2023-05-31 15:27:50,752 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213108120000 - create table shedlock" [non-transactional]
2023-05-31 15:27:50,842 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213109120000 - add enabled" [non-transactional]
2023-05-31 15:27:51,120 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213110120000 - add last execution info data job" [non-transactional]
2023-05-31 15:27:51,730 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213111120000 - create index idx data job execution job name start time" [non-transactional]
2023-05-31 15:27:52,038 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20213112120000 - create index idx data job execution job name end time" [non-transactional]
2023-05-31 15:27:52,353 INFO [OpId:] main o.f.c.internal.command.DbMigrate Migrating schema "defaultdb" to version "20230410140000 - add column job python version to data job execution table" [non-transactional]
2023-05-31 15:27:52,649 INFO [OpId:] main o.f.c.internal.command.DbMigrate Successfully applied 16 migrations to schema "defaultdb", now at version v20230410140000 (execution time 00:03.875s)
2023-05-31 15:27:52,727 INFO [OpId:] main o.h.jpa.internal.util.LogHelper HHH000204: Processing PersistenceUnitInfo [name: default]
2023-05-31 15:27:52,769 INFO [OpId:] main org.hibernate.Version HHH000412: Hibernate ORM core version 5.6.15.Final
2023-05-31 15:27:52,926 INFO [OpId:] main o.h.annotations.common.Version HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2023-05-31 15:27:53,029 INFO [OpId:] main org.hibernate.dialect.Dialect HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL94Dialect
2023-05-31 15:27:53,670 INFO [OpId:] main h.e.t.j.p.i.JtaPlatformInitiator HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2023-05-31 15:27:53,679 INFO [OpId:] main ontainerEntityManagerFactoryBean Initialized JPA EntityManagerFactory for persistence unit 'default'
2023-05-31 15:27:54,281 INFO [OpId:] main v.t.s.k.ControlKubernetesService Configuration used: kubeconfig: /root/.kube/config, namespace:
2023-05-31 15:27:54,281 INFO [OpId:] main v.t.s.k.ControlKubernetesService Will use default client
2023-05-31 15:27:54,392 INFO [OpId:] main v.t.s.k.ControlKubernetesService kubernetes namespace: default
2023-05-31 15:27:54,486 INFO [OpId:] main v.t.s.k.ControlKubernetesService The internal datajob template is valid.
2023-05-31 15:27:54,524 INFO [OpId:] main .t.s.k.DataJobsKubernetesService Configuration used: kubeconfig: /etc/secrets/deployment-kubeconfig, namespace:
2023-05-31 15:27:54,524 INFO [OpId:] main .t.s.k.DataJobsKubernetesService Will use default client
2023-05-31 15:27:54,527 INFO [OpId:] main .t.s.k.DataJobsKubernetesService kubernetes namespace: default
2023-05-31 15:27:54,533 INFO [OpId:] main .t.s.k.DataJobsKubernetesService The internal datajob template is valid.
2023-05-31 15:27:54,535 INFO [OpId:] main t.s.c.EmptyCredentialsRepository Credentials repository used will be empty - no credentials.
2023-05-31 15:27:55,580 INFO [OpId:] main c.v.t.s.SecurityConfiguration Security is disabled.
2023-05-31 15:27:55,617 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will secure any request with [org.springframework.security.web.session.DisableEncodeUrlFilter@1000303a, org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@46763680, org.springframework.security.web.context.SecurityContextPersistenceFilter@c197f46, org.springframework.security.web.header.HeaderWriterFilter@1398e3aa, org.springframework.security.web.authentication.logout.LogoutFilter@4a48fe63, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@25ee6683, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@5aeaee3, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@6b0796d4, org.springframework.security.web.session.SessionManagementFilter@ba76911, org.springframework.security.web.access.ExceptionTranslationFilter@1d7d2345, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@60ee1a29]
2023-05-31 15:27:55,623 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,623 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/']
2023-05-31 15:27:55,624 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/api-docs']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,624 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/api-docs']
2023-05-31 15:27:55,624 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/api-docs/**']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,624 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/api-docs/**']
2023-05-31 15:27:55,624 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/swagger-resources/**']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,624 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/swagger-resources/**']
2023-05-31 15:27:55,624 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/swagger-ui/*']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,624 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/swagger-ui/*']
2023-05-31 15:27:55,624 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/swagger-ui.html']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,624 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/swagger-ui.html']
2023-05-31 15:27:55,625 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/webjars/**']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,625 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/webjars/**']
2023-05-31 15:27:55,625 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/debug/prometheus']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,625 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/debug/prometheus']
2023-05-31 15:27:55,625 WARN [OpId:] main o.s.s.c.a.w.builders.WebSecurity You are asking Spring Security to ignore Ant [pattern='/data-jobs/debug/**']. This is not recommended -- please use permitAll via HttpSecurity#authorizeHttpRequests instead.
2023-05-31 15:27:55,625 INFO [OpId:] main s.s.w.DefaultSecurityFilterChain Will not secure Ant [pattern='/data-jobs/debug/**']
2023-05-31 15:27:56,467 INFO [OpId:] main .s.b.a.e.w.EndpointLinksResolver Exposing 16 endpoint(s) beneath base path '/data-jobs/debug'
2023-05-31 15:27:56,502 INFO [OpId:] main o.a.c.http11.Http11NioProtocol Starting ProtocolHandler ["http-nio-8092"]
2023-05-31 15:27:56,517 INFO [OpId:] main o.s.b.w.e.tomcat.TomcatWebServer Tomcat started on port(s): 8092 (http) with context path ''
2023-05-31 15:27:56,545 INFO [OpId:] main c.v.t.ControlplaneApplication Started ControlplaneApplication in 11.92 seconds (JVM running for 12.375)
2023-05-31 15:28:06,634 INFO [OpId:] thread-1 .t.s.k.DataJobsKubernetesService Start watching jobs with labels: {com.vmware.taurus/type=DataJob}
2023-05-31 15:28:22,679 INFO [OpId:] 092-exec-1 o.a.c.c.C.[.[localhost].[/] Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-05-31 15:28:22,679 INFO [OpId:] 092-exec-1 o.s.w.servlet.DispatcherServlet Initializing Servlet 'dispatcherServlet'
2023-05-31 15:28:22,681 INFO [OpId:] 092-exec-1 o.s.w.servlet.DispatcherServlet Completed initialization in 2 ms
2023-05-31 15:29:23,707 INFO [OpId:11613df41f4448d1] 092-exec-6 c.v.t.s.m.DataJobMetrics The info gauge for data job gdp-execution-id-example was created
2023-05-31 15:29:23,707 INFO [OpId:11613df41f4448d1] 092-exec-6 c.v.t.s.m.DataJobMetrics The notification delay gauge for data job gdp-execution-id-example was created
2023-05-31 15:29:23,717 INFO [OpId:11613df41f4448d1] 092-exec-6 c.v.t.service.diag.HttpTracer [user:anonymous] POST http://localhost/data-jobs/for-team/taurus/jobs?name=gdp-execution-id-example -> 201
2023-05-31 15:29:46,304 INFO [OpId:773b757f8129402b] 092-exec-8 c.v.t.service.diag.HttpTracer [user:anonymous] POST http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example/sources?reason=test -> 200
2023-05-31 15:29:46,517 INFO [OpId:773b757f8129402b] 092-exec-9 c.v.t.service.diag.HttpTracer [user:anonymous] GET http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example -> 200
2023-05-31 15:29:46,551 INFO [OpId:773b757f8129402b] 92-exec-10 c.v.t.service.diag.HttpTracer [user:anonymous] PUT http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example -> 200
2023-05-31 15:29:46,581 INFO [OpId:773b757f8129402b] 092-exec-1 c.v.t.service.diag.HttpTracer [user:anonymous] POST http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example/deployments -> 202
2023-05-31 15:29:46,582 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.DeploymentService Starting deployment of job gdp-execution-id-example
2023-05-31 15:29:46,604 WARN [OpId:773b757f8129402b] thread-2 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"cronjobs.batch \"gdp-execution-id-example\" not found","reason":"NotFound","details":{"name":"gdp-execution-id-example","group":"batch","kind":"cronjobs"},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[246], content-type=[application/json], date=[Wed, 31 May 2023 15:29:46 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:29:46,607 WARN [OpId:773b757f8129402b] thread-2 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server could not find the requested resource","reason":"NotFound","details":{},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[174], content-type=[application/json], date=[Wed, 31 May 2023 15:29:46 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:29:46,608 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.JobImageBuilder Build data job image for job gdp-execution-id-example. Image name: localhost:5000/gdp-execution-id-example:9ac7dd60d4d151e509b0ad2f990c6f13b2f75d23
2023-05-31 15:29:46,636 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.JobImageBuilder Creating builder job builder-gdp-execution-id-example for data job version 9ac7dd60d4d151e509b0ad2f990c6f13b2f75d23
2023-05-31 15:30:08,322 WARN [OpId:582ec7c7277c4b8c] 092-exec-5 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"cronjobs.batch \"gdp-execution-id-example\" not found","reason":"NotFound","details":{"name":"gdp-execution-id-example","group":"batch","kind":"cronjobs"},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[246], content-type=[application/json], date=[Wed, 31 May 2023 15:30:08 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:30:08,325 WARN [OpId:582ec7c7277c4b8c] 092-exec-5 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server could not find the requested resource","reason":"NotFound","details":{},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[174], content-type=[application/json], date=[Wed, 31 May 2023 15:30:08 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:30:08,328 INFO [OpId:582ec7c7277c4b8c] 092-exec-5 c.v.t.service.diag.HttpTracer [user:anonymous] GET http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example/deployments -> 200
2023-05-31 15:30:18,944 WARN [OpId:94b8131e7fe04bb1] 092-exec-7 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"cronjobs.batch \"gdp-execution-id-example\" not found","reason":"NotFound","details":{"name":"gdp-execution-id-example","group":"batch","kind":"cronjobs"},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[246], content-type=[application/json], date=[Wed, 31 May 2023 15:30:18 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:30:18,946 WARN [OpId:94b8131e7fe04bb1] 092-exec-7 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server could not find the requested resource","reason":"NotFound","details":{},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[174], content-type=[application/json], date=[Wed, 31 May 2023 15:30:18 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:30:18,947 INFO [OpId:94b8131e7fe04bb1] 092-exec-7 c.v.t.service.diag.HttpTracer [user:anonymous] GET http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example/deployments -> 200
2023-05-31 15:30:27,617 WARN [OpId:bb81779e692f4ed0] 092-exec-9 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"cronjobs.batch \"gdp-execution-id-example\" not found","reason":"NotFound","details":{"name":"gdp-execution-id-example","group":"batch","kind":"cronjobs"},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[246], content-type=[application/json], date=[Wed, 31 May 2023 15:30:27 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:30:27,619 WARN [OpId:bb81779e692f4ed0] 092-exec-9 .t.s.k.DataJobsKubernetesService Could not read cron job: gdp-execution-id-example; reason: com.vmware.taurus.exception.KubernetesException: An issue occurred:
context=KUBERNETES encountered an error:
Kubernetes API Exception Details:
response body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server could not find the requested resource","reason":"NotFound","details":{},"code":404}
response headers: {cache-control=[no-cache, private], content-length=[174], content-type=[application/json], date=[Wed, 31 May 2023 15:30:27 GMT], x-kubernetes-pf-flowschema-uid=[63773c60-99d0-40c8-bbe4-347cfabd0251], x-kubernetes-pf-prioritylevel-uid=[c958bda8-a8d3-4f1d-8288-1762e91b385c]}.,
problem=The external system may be experiencing intermittent issues or there might be permanent misconfiguration or outage.,
consequences=The current API operation failed.,
countermeasures=Try the operation again in a few minutes and open a ticket to the SRE team if the problem persists.
2023-05-31 15:30:27,620 INFO [OpId:bb81779e692f4ed0] 092-exec-9 c.v.t.service.diag.HttpTracer [user:anonymous] GET http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example/deployments -> 200
2023-05-31 15:31:06,972 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.JobImageBuilder Get logs of builder job builder-gdp-execution-id-example
2023-05-31 15:31:06,972 INFO [OpId:773b757f8129402b] thread-2 v.t.s.k.ControlKubernetesService Get logs for pod builder-gdp-execution-id-example
2023-05-31 15:31:06,998 INFO [OpId:773b757f8129402b] thread-2 v.t.s.k.ControlKubernetesService Retrieving logs for Pod with name: builder-gdp-execution-id-example
2023-05-31 15:31:07,001 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.JobImageBuilder Builder job builder-gdp-execution-id-example finished successfully. Will delete it now
2023-05-31 15:31:07,026 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.DeploymentService Image localhost:5000/gdp-execution-id-example:9ac7dd60d4d151e509b0ad2f990c6f13b2f75d23 has been built. Will now schedule job gdp-execution-id-example for execution
2023-05-31 15:31:07,026 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.JobImageDeployer Update cron job for data job gdp-execution-id-example
2023-05-31 15:31:07,081 INFO [OpId:773b757f8129402b] thread-2 c.v.t.s.deploy.DeploymentService Successfully updated job: gdp-execution-id-example with version: 9ac7dd60d4d151e509b0ad2f990c6f13b2f75d23
2023-05-31 15:31:11,640 INFO [OpId:07f8d8faea794fb4] 092-exec-9 c.v.t.service.diag.HttpTracer [user:anonymous] GET http://localhost/data-jobs/for-team/taurus/jobs/gdp-execution-id-example/deployments -> 200
2023-05-31 15:32:05,021 INFO [OpId:] thread-1 c.v.t.s.m.DataJobMonitorCron Termination message of Data Job gdp-execution-id-example with execution gdp-execution-id-example-1685547120: null
2023-05-31 15:32:05,055 INFO [OpId:] thread-1 c.v.t.s.m.DataJobMetrics The termination status gauge for data job gdp-execution-id-example was created
2023-05-31 15:32:05,080 INFO [OpId:] thread-1 c.v.t.s.m.DataJobMonitorCron Termination message of Data Job gdp-execution-id-example with execution gdp-execution-id-example-1685547120: null
2023-05-31 15:33:06,916 INFO [OpId:] thread-1 .t.s.k.DataJobsKubernetesService Finish watching jobs with labels: {com.vmware.taurus/type=DataJob}
2023-05-31 15:33:07,936 INFO [OpId:] thread-1 .t.s.k.DataJobsKubernetesService Start watching jobs with labels: {com.vmware.taurus/type=DataJob}