Asynchronous initialization: Application still restarts after 10 seconds

[maschnetwork]

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    |

[deki]

Thanks for your issue report. I've just released a new version with two system properties that allow you to modify grace time and timeout. Please see the updated docs https://github.com/awslabs/aws-serverless-java-container/wiki/Quick-start---Spring-Boot2#asynchronous-initialization and let me know if something is unclear.