K8S deployment got error, "Load new/updated app access keys failed"

[Backstage2539]

Hi, here is the configserver log in K8s pod:

[Backstage2539]

OpenJDK 64-Bit Server VM warning: UseCMSCompactAtFullCollection is deprecated and will likely be removed in a future release.
OpenJDK 64-Bit Server VM warning: CMSFullGCsBeforeCompaction is deprecated and will likely be removed in a future release.
_ _ _
/ \ _ __ ___ | | | ___
/ _ \ | '_ \ / _ | | |/ _
/ ___ | |) | () | | | () |
// _\ ./ _/|||___/
|_|

:: Spring Boot :: (v2.6.8)

2023-09-20 17:15:39.420 INFO 1 --- [ main] c.c.f.a.c.ConfigServiceApplication : Starting ConfigServiceApplication v2.1.0 using Java 1.8.0_342 on apollo-service-dev-apollo-configservice-777699c645-65bl7 with PID 1 (/apollo-configservice/apollo-configservice-2.1.0.jar started by root in /apollo-configservice)
2023-09-20 17:15:39.513 INFO 1 --- [ main] c.c.f.a.c.ConfigServiceApplication : The following 2 profiles are active: "github", "kubernetes"
2023-09-20 17:16:01.113 INFO 1 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2023-09-20 17:16:03.919 INFO 1 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 2705 ms. Found 18 JPA repository interfaces.
2023-09-20 17:16:08.725 INFO 1 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=15b1ab78-05c8-3aad-8ce5-1cd9996e9fd2
2023-09-20 17:16:17.827 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2023-09-20 17:16:18.012 INFO 1 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2023-09-20 17:16:18.012 INFO 1 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.63]
2023-09-20 17:16:18.713 INFO 1 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2023-09-20 17:16:18.714 INFO 1 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 38593 ms
2023-09-20 17:16:22.422 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2023-09-20 17:16:25.313 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2023-09-20 17:16:26.327 INFO 1 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2023-09-20 17:16:27.126 INFO 1 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.6.9.Final
2023-09-20 17:16:29.746 INFO 1 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2023-09-20 17:16:31.516 INFO 1 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.MySQL57Dialect
2023-09-20 17:16:32.911 WARN 1 --- [ main] org.hibernate.cfg.AnnotationBinder : HHH000503: A class should not be annotated with both @Inheritance and @MappedSuperclass. @Inheritance will be ignored for: com.ctrip.framework.apollo.common.entity.BaseEntity.
2023-09-20 17:16:46.624 INFO 1 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2023-09-20 17:16:46.912 INFO 1 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2023-09-20 17:16:58.718 WARN 1 --- [ main] c.c.f.f.i.p.DefaultApplicationProvider : app.id is not available from System Property and /META-INF/app.properties. It is set to null
2023-09-20 17:16:58.719 WARN 1 --- [ main] c.c.f.f.i.p.DefaultApplicationProvider : app.label is not available from System Property and /META-INF/app.properties. It is set to null
2023-09-20 17:16:58.934 INFO 1 --- [ main] c.c.f.f.i.p.DefaultServerProvider : Environment is set to null. Because it is not available in either (1) JVM system property 'env', (2) OS env variable 'ENV' nor (3) property 'env' from the properties InputStream.
2023-09-20 17:16:58.935 INFO 1 --- [ main] c.c.f.a.biz.service.BizDBPropertySource : Load config from DB : item.key.length.limit = 128
2023-09-20 17:16:58.936 INFO 1 --- [ main] c.c.f.a.biz.service.BizDBPropertySource : Load config from DB : item.value.length.limit = 20000
2023-09-20 17:16:58.936 INFO 1 --- [ main] c.c.f.a.biz.service.BizDBPropertySource : Load config from DB : eureka.service.url = http://localhost:8080/eureka/
2023-09-20 17:16:58.936 INFO 1 --- [ main] c.c.f.a.biz.service.BizDBPropertySource : Load config from DB : namespace.lock.switch = false
2023-09-20 17:16:58.936 INFO 1 --- [ main] c.c.f.a.biz.service.BizDBPropertySource : Load config from DB : config-service.cache.enabled = false
2023-09-20 17:17:22.620 WARN 1 --- [ main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2023-09-20 17:17:29.414 INFO 1 --- [ main] o.s.s.web.DefaultSecurityFilterChain : Will secure any request with [org.springframework.security.web.session.DisableEncodeUrlFilter@4fe8e318, org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@21e15093, org.springframework.security.web.context.SecurityContextPersistenceFilter@4f9e9c21, org.springframework.security.web.header.HeaderWriterFilter@6bf34912, org.springframework.security.web.authentication.logout.LogoutFilter@7e916dc2, org.springframework.security.web.authentication.www.BasicAuthenticationFilter@5625e7e1, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@7bf2e475, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@6c2a33af, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@62cf873a, org.springframework.security.web.session.SessionManagementFilter@30ce78e3, org.springframework.security.web.access.ExceptionTranslationFilter@60e5db1d]
2023-09-20 17:17:29.420 INFO 1 --- [ main] o.s.s.web.DefaultSecurityFilterChain : Will secure any request with [org.springframework.security.web.session.DisableEncodeUrlFilter@267309f7, org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@46878216, org.springframework.security.web.context.SecurityContextPersistenceFilter@1f2d0ca2, org.springframework.security.web.header.HeaderWriterFilter@452a32f2, org.springframework.security.web.authentication.logout.LogoutFilter@7af2ee23, org.springframework.security.web.authentication.www.BasicAuthenticationFilter@5d10e2b6, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@e353e1d, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@1a1c308b, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@2b69ff13, org.springframework.security.web.session.SessionManagementFilter@2db75e32, org.springframework.security.web.access.ExceptionTranslationFilter@44cab872]
2023-09-20 17:17:45.224 INFO 1 --- [ main] DiscoveryClientOptionalArgsConfiguration : Eureka HTTP Client uses Jersey
2023-09-20 17:17:47.811 WARN 1 --- [ main] iguration$LoadBalancerCaffeineWarnLogger : Spring Cloud LoadBalancer is currently working with the default cache. While this cache implementation is useful for development and tests, it's recommended to use Caffeine cache in production.You can switch to using Caffeine cache, by adding it and org.springframework.cache.caffeine.CaffeineCacheManager to the classpath.
2023-09-20 17:17:48.014 INFO 1 --- [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 4 endpoint(s) beneath base path ''
2023-09-20 17:17:49.616 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2023-09-20 17:17:49.816 INFO 1 --- [ main] c.c.f.a.c.ConfigServiceApplication : Started ConfigServiceApplication in 138.396 seconds (JVM running for 145.17)
2023-09-20 17:17:50.910 INFO 1 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-09-20 17:17:50.918 INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown initiated...
2023-09-20 17:17:51.211 ERROR 1 --- [viceWithCache-1] c.c.f.a.c.s.AccessKeyServiceWithCache : Load new/updated app access keys failed

org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'dataSourceScriptDatabaseInitializer': Singleton bean creation not allowed while singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:220)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
at org.springframework.beans.factory.support.DefaultListableBeanFactory$1.orderedStream(DefaultListableBeanFactory.java:481)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.detectPersistenceExceptionTranslators(PersistenceExceptionTranslationInterceptor.java:167)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:149)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:145)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy152.findFirst500ByDataChangeLastModifiedTimeGreaterThanOrderByDataChangeLastModifiedTimeAsc(Unknown Source)
at sun.reflect.GeneratedMethodAccessor134.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
at com.ctrip.framework.apollo.common.aop.RepositoryAspect.invokeWithCatTransaction(RepositoryAspect.java:43)
at sun.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy152.findFirst500ByDataChangeLastModifiedTimeGreaterThanOrderByDataChangeLastModifiedTimeAsc(Unknown Source)
at com.ctrip.framework.apollo.configservice.service.AccessKeyServiceWithCache.loadNewAndUpdatedAccessKeys(AccessKeyServiceWithCache.java:145)
at com.ctrip.framework.apollo.configservice.service.AccessKeyServiceWithCache.scanNewAndUpdatedAccessKeys(AccessKeyServiceWithCache.java:116)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)

2023-09-20 17:17:51.211 ERROR 1 --- [essageScanner-1] c.c.f.a.b.message.ReleaseMessageScanner : Scan and send message failed

org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'dataSourceScriptDatabaseInitializer': Singleton bean creation not allowed while singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:220)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
at org.springframework.beans.factory.support.DefaultListableBeanFactory$1.orderedStream(DefaultListableBeanFactory.java:481)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.detectPersistenceExceptionTranslators(PersistenceExceptionTranslationInterceptor.java:167)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:149)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy168.findAllById(Unknown Source)
at sun.reflect.GeneratedMethodAccessor278.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
at com.ctrip.framework.apollo.common.aop.RepositoryAspect.invokeWithCatTransaction(RepositoryAspect.java:43)
at sun.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy168.findAllById(Unknown Source)
at com.ctrip.framework.apollo.biz.message.ReleaseMessageScanner.scanMissingMessages(ReleaseMessageScanner.java:132)
at com.ctrip.framework.apollo.biz.message.ReleaseMessageScanner.lambda$afterPropertiesSet$0(ReleaseMessageScanner.java:73)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)

2023-09-20 17:17:51.318 INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown completed.

[Backstage2539]

And there is adminservice error:
2023-09-20 20:47:22.757 INFO 1 --- [ main] DiscoveryClientOptionalArgsConfiguration : Eureka HTTP Client uses RestTemplate.
2023-09-20 20:47:25.752 WARN 1 --- [ main] iguration$LoadBalancerCaffeineWarnLogger : Spring Cloud LoadBalancer is currently working with the default cache. While this cache implementation is useful for development and tests, it's recommended to use Caffeine cache in production.You can switch to using Caffeine cache, by adding it and org.springframework.cache.caffeine.CaffeineCacheManager to the classpath.
2023-09-20 20:47:25.861 INFO 1 --- [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 4 endpoint(s) beneath base path ''
2023-09-20 20:47:27.161 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8090 (http) with context path '/config'
2023-09-20 20:47:27.356 INFO 1 --- [ main] c.c.f.a.a.AdminServiceApplication : Started AdminServiceApplication in 130.379 seconds (JVM running for 136.694)
2023-09-20 20:47:27.955 INFO 1 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-09-20 20:47:27.959 INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown initiated...
2023-09-20 20:47:28.162 INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown completed.

[nobodyiam]

The application appears to be closing unexpectedly. Enable debug-level logging for detailed insights.

2023-09-20 17:17:49.816 INFO 1 --- [ main] c.c.f.a.c.ConfigServiceApplication : Started ConfigServiceApplication in 138.396 seconds (JVM running for 145.17)
2023-09-20 17:17:50.910 INFO 1 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-09-20 17:17:50.918 INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown initiated...

[Backstage2539]

Thanks for replying, another question. How to enable debug-level? Can i set it in values.yaml file when i deploy it to K8s. I cannot find any introduction in the guidance docs.

[nobodyiam]

see 4.5. Log Levels for more information.

[Backstage2539]

Solved by adding following config, because i have found that if the starting time shorts than 120s, then the deploymeny worked out.
liveness: initialDelaySeconds: 120 periodSeconds: 10