Asynchronous initialization: Application still restarts after 10 seconds #450
Description
To help us debug your issue fill in the basic information below using the options provided
Serverless Java Container version: 1.6
Implementations: Spring Boot 2
Framework version: SpringBoot 2.6.2
Frontend service: REST API
Deployment method: CDK
Scenario
I have a Spring Boot application on AWS Lambda that takes around 12-14 Seconds to initialize (Jpa/Hibernate, PostgreSQL, AWS-SDK). Therefore choosing Async-Init as described here.
Expected behavior
Application should constantly start between 12-14 Seconds.
Actual behavior
Applications takes double the time on a few occasions as it seems that the process gets interrupted by the runtime and Spring application is re-started. As this happens almost exactly after 10 seconds this might be related to AWS Lambda init phase is limited to 10 seconds see here.
Full log output
Paste the full log output from the Lambda function's CloudWatch logs
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| timestamp | message |
|---------------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 1647619399874 | 16:03:19.868 [main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler |
| 1647619400248 | 16:03:20.246 [main] INFO com.amazonaws.serverless.proxy.AsyncInitializationWrapper - Async initialization will wait for 8465ms |
| 1647619400248 | 16:03:20.247 [Thread-0] INFO com.amazonaws.serverless.proxy.AsyncInitializationWrapper - Starting async initializer |
| 1647619401711 | . ____ _ __ _ _ |
| 1647619401711 | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \ |
| 1647619401711 | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \ |
| 1647619401711 | \\/ ___)| |_)| | | | | || (_| | ) ) ) ) |
| 1647619401711 | ' |____| .__|_| |_|_| |_\__, | / / / / |
| 1647619401711 | =========|_|==============|___/=/_/_/_/ |
| 1647619401732 | :: Spring Boot :: |
| 1647619402122 | 2022-03-18 16:03:22.119 INFO 9 --- [ Thread-0] o.s.boot.SpringApplication : Starting application using Java 11.0.14.1 on X with PID 9 (started by sbx_user1051 in /var/task) |
| 1647619402123 | 2022-03-18 16:03:22.123 INFO 9 --- [ Thread-0] o.s.boot.SpringApplication : No active profile set, falling back to default profiles: default |
| 1647619404044 | 2022-03-18 16:03:24.044 INFO 9 --- [ Thread-0] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode. |
| 1647619404195 | 2022-03-18 16:03:24.194 INFO 9 --- [ Thread-0] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 124 ms. Found 1 JPA repository interfaces. |
| 1647619405145 | 2022-03-18 16:03:25.145 INFO 9 --- [ Thread-0] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext |
| 1647619405145 | 2022-03-18 16:03:25.145 INFO 9 --- [ Thread-0] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 2885 ms |
| 1647619405572 | 2022-03-18 16:03:25.570 DEBUG 9 --- [ Thread-0] c.a.s.p.i.servlet.AwsServletContext : Adding filter 'characterEncodingFilter' from org.springframework.boot.web.servlet.filter.OrderedCharacterEncodingFilter@6b571429 |
| 1647619405576 | 2022-03-18 16:03:25.576 DEBUG 9 --- [ Thread-0] c.a.s.p.i.servlet.AwsServletContext : Adding filter 'formContentFilter' from org.springframework.boot.web.servlet.filter.OrderedFormContentFilter@13792c8e |
| 1647619405576 | 2022-03-18 16:03:25.576 DEBUG 9 --- [ Thread-0] c.a.s.p.i.servlet.AwsServletContext : Adding filter 'requestContextFilter' from org.springframework.boot.web.servlet.filter.OrderedRequestContextFilter@3b022687 |
| 1647619406016 | 2022-03-18 16:03:26.016 INFO 9 --- [ Thread-0] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting... |
| 1647619406841 | 2022-03-18 16:03:26.840 INFO 9 --- [ Thread-0] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed. |
| 1647619407084 | 2022-03-18 16:03:27.084 INFO 9 --- [ Thread-0] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default] |
| 1647619407359 | 2022-03-18 16:03:27.359 INFO 9 --- [ Thread-0] org.hibernate.Version : HHH000412: Hibernate ORM core version [WORKING] |
| 1647619407844 | 2022-03-18 16:03:27.843 INFO 9 --- [ Thread-0] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final} |
| 1647619408230 | 2022-03-18 16:03:28.230 INFO 9 --- [ Thread-0] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect |
| 1647619408816 | START RequestId: f3c2bd44-cdee-41f7-b453-3c7dXX10043e Version: $LATEST |
| 1647619410338 | 16:03:30.311 [main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler |
| 1647619411058 | 16:03:31.055 [Thread-0] INFO com.amazonaws.serverless.proxy.AsyncInitializationWrapper - Starting async initializer |
| 1647619411058 | 16:03:31.058 [main] INFO com.amazonaws.serverless.proxy.AsyncInitializationWrapper - Async initialization will wait for 7662ms |
| 1647619412926 | . ____ _ __ _ _ |
| 1647619412926 | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \ |
| 1647619412926 | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \ |
| 1647619412926 | \\/ ___)| |_)| | | | | || (_| | ) ) ) ) |
| 1647619412926 | ' |____| .__|_| |_|_| |_\__, | / / / / |
| 1647619412926 | =========|_|==============|___/=/_/_/_/ |
| 1647619412931 | :: Spring Boot :: |
| 1647619413364 | 2022-03-18 16:03:33.363 INFO 9 --- [ Thread-0] o.s.boot.SpringApplication : Starting application using Java 11.0.14.1 on X with PID 9 (started by sbx_user1051 in /var/task) |
| 1647619413365 | 2022-03-18 16:03:33.365 INFO 9 --- [ Thread-0] o.s.boot.SpringApplication : No active profile set, falling back to default profiles: default |
| 1647619415765 | 2022-03-18 16:03:35.764 INFO 9 --- [ Thread-0] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode. |
| 1647619415901 | 2022-03-18 16:03:35.901 INFO 9 --- [ Thread-0] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 114 ms. Found 1 JPA repository interfaces. |
| 1647619417130 | 2022-03-18 16:03:37.130 INFO 9 --- [ Thread-0] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext |
| 1647619417131 | 2022-03-18 16:03:37.130 INFO 9 --- [ Thread-0] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 3598 ms |
| 1647619417990 | 2022-03-18 16:03:37.983 DEBUG 9 --- [ Thread-0] c.a.s.p.i.servlet.AwsServletContext : Adding filter 'characterEncodingFilter' from org.springframework.boot.web.servlet.filter.OrderedCharacterEncodingFilter@333cae36 |
Metadata
Metadata
Assignees
Labels
No labels