Spring Boot Lambda Startup multiple times #210

DIGIT-SAAS · 2018-11-12T08:08:17Z

Framework version: aws-serverless-java-container-spring:1.2
Implementations: Spring Boot / Spring Data / spring-data-dynamodb

Scenario

Running simple Spring Boot Backend Service, which Queries DynamoDB via Spring Data DynamoDB.

Expected behavior

On each request I can see Spring Boot Process in Cloudwatch. The request should be finished within seconds.

Actual behavior

I can see, that Spring Boot starts three times in the Cloudwatch Log. The request takes approx. 1 Minute to complete. The request is on hold while it boots up three times. (see logs)

Steps to reproduce

mvn archetype:generate -DgroupId=my.service -DartifactId=my-service -Dversion=1.0-SNAPSHOT \ -DarchetypeGroupId=com.amazonaws.serverless.archetypes \ -DarchetypeArtifactId=aws-serverless-springboot-archetype \ -DarchetypeVersion=1.2
Add Spring Data DynamoDB and do some queries: https://github.com/derjust/spring-data-dynamodb/wiki

Question

Did I have some misconfiguration here or is it a bug?

Full log output

07:31:15.131 [main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler
07:31:15.485 [main] INFO com.amazonaws.serverless.proxy.internal.servlet.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath

. ____ _ __ _ _
/ / ____ __ _ ()_ __ __ _
( ( )___ | _ | | | _ / _ |
/ )| |)| | | | | || (| | ) ) ) )
|| .__|| ||| |, | / / / /
=========||==============|/=///_/
:: Spring Boot ::

2018-11-12 07:31:17.244 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : Starting Application on ip-10-134-129-208.eu-west-1.compute.internal with PID 1 (/var/task started by sbx_user1059 in /)
2018-11-12 07:31:17.245 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : The following profiles are active: lambda
2018-11-12 07:31:17.325 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@591f989e: startup date [Mon Nov 12 07:31:17 UTC 2018]; root of context hierarchy
2018-11-12 07:31:18.462 INFO 1 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Overriding bean definition for bean handlerExceptionResolver with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.web.servlet.config.annotation.DelegatingWebMvcConfiguration; factoryMethodName=handlerExceptionResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/web/servlet/config/annotation/DelegatingWebMvcConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=config; factoryMethodName=handlerExceptionResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/keyholesoftware/lambda/config/Config.class]]
2018-11-12 07:31:19.801 INFO 1 --- [ main] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 javax.inject.Inject annotation found and supported for autowiring
2018-11-12 07:31:20.003 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext
2018-11-12 07:31:20.004 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 2682 ms
2018-11-12 07:31:20.602 INFO 1 --- [ main] o.s.b.w.servlet.ServletRegistrationBean : Servlet dispatcherServlet mapped to [/]
2018-11-12 07:31:20.604 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring FrameworkServlet dispatcherServlet
2018-11-12 07:31:20.604 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : FrameworkServlet dispatcherServlet: initialization started
2018-11-12 07:31:22.868 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Spring Data DynamoDB Version: DEVELOPMENT (DEVELOPMENT)
2018-11-12 07:31:22.870 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Spring Data Version: null
2018-11-12 07:31:22.870 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : AWS SDK Version: 1.11.34
2018-11-12 07:31:22.870 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Java Version: 1.8.0_181 - OpenJDK 64-Bit Server VM 25.181-b13
2018-11-12 07:31:22.870 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Platform Details: Linux 4.14.72-68.55.amzn1.x86_64
2018-11-12 07:31:23.426 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[GET]} onto public java.util.List<com.keyholesoftware.lambda.model.Language> com.keyholesoftware.lambda.rest.LanguageResource.listLambdaLanguages()
2018-11-12 07:31:23.427 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[POST]} onto public java.util.List<java.lang.String> com.keyholesoftware.lambda.rest.LanguageResource.postLambdaLanguages(java.lang.String)
2018-11-12 07:31:23.441 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error]} onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-11-12 07:31:23.442 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error],produces=[text/html]} onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-11-12 07:31:23.586 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[GET]} onto public java.util.List<com.keyholesoftware.lambda.model.Language> com.keyholesoftware.lambda.rest.LanguageResource.listLambdaLanguages()
2018-11-12 07:31:23.587 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[POST]} onto public java.util.List<java.lang.String> com.keyholesoftware.lambda.rest.LanguageResource.postLambdaLanguages(java.lang.String)
2018-11-12 07:31:23.606 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error]} onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-11-12 07:31:23.606 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error],produces=[text/html]} onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-11-12 07:31:23.943 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@591f989e: startup date [Mon Nov 12 07:31:17 UTC 2018]; root of context hierarchy
2018-11-12 07:31:24.026 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@591f989e: startup date [Mon Nov 12 07:31:17 UTC 2018]; root of context hierarchy
2018-11-12 07:31:24.163 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : FrameworkServlet dispatcherServlet: initialization completed in 3559 ms
START RequestId: ee858242-e64c-11e8-b920-f99fde59ed8e Version: $LATEST
07:31:24.811 [main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler
07:31:25.163 [main] INFO com.amazonaws.serverless.proxy.internal.servlet.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath

. ____ _ __ _ _
/ / ____ __ _ ()_ __ __ _
( ( )___ | _ | | | _ / _ |
/ )| |)| | | | | || (| | ) ) ) )
|| .__|| ||| |, | / / / /
=========||==============|/=///_/
:: Spring Boot ::

2018-11-12 07:31:26.588 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : Starting Application on ip-10-134-129-208.eu-west-1.compute.internal with PID 1 (/var/task started by sbx_user1059 in /)
2018-11-12 07:31:26.601 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : The following profiles are active: lambda
2018-11-12 07:31:26.645 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2aafb23c: startup date [Mon Nov 12 07:31:26 UTC 2018]; root of context hierarchy
2018-11-12 07:31:27.723 INFO 1 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Overriding bean definition for bean handlerExceptionResolver with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.web.servlet.config.annotation.DelegatingWebMvcConfiguration; factoryMethodName=handlerExceptionResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/web/servlet/config/annotation/DelegatingWebMvcConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=config; factoryMethodName=handlerExceptionResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/keyholesoftware/lambda/config/Config.class]]
2018-11-12 07:31:28.965 INFO 1 --- [ main] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 javax.inject.Inject annotation found and supported for autowiring
2018-11-12 07:31:29.190 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext
2018-11-12 07:31:29.191 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 2548 ms
2018-11-12 07:31:29.645 INFO 1 --- [ main] o.s.b.w.servlet.ServletRegistrationBean : Servlet dispatcherServlet mapped to [/]
2018-11-12 07:31:29.646 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring FrameworkServlet dispatcherServlet
2018-11-12 07:31:29.646 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : FrameworkServlet dispatcherServlet: initialization started
2018-11-12 07:31:31.327 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Spring Data DynamoDB Version: DEVELOPMENT (DEVELOPMENT)
2018-11-12 07:31:31.329 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Spring Data Version: null
2018-11-12 07:31:31.329 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : AWS SDK Version: 1.11.34
2018-11-12 07:31:31.329 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Java Version: 1.8.0_181 - OpenJDK 64-Bit Server VM 25.181-b13
2018-11-12 07:31:31.329 INFO 1 --- [ main] o.s.s.d.d.r.s.DynamoDBRepositoryFactory : Platform Details: Linux 4.14.72-68.55.amzn1.x86_64
2018-11-12 07:31:31.866 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[GET]} onto public java.util.List<com.keyholesoftware.lambda.model.Language> com.keyholesoftware.lambda.rest.LanguageResource.listLambdaLanguages()
2018-11-12 07:31:31.868 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[POST]} onto public java.util.List<java.lang.String> com.keyholesoftware.lambda.rest.LanguageResource.postLambdaLanguages(java.lang.String)
2018-11-12 07:31:31.887 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error]} onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-11-12 07:31:31.888 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error],produces=[text/html]} onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-11-12 07:31:32.003 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[GET]} onto public java.util.List<com.keyholesoftware.lambda.model.Language> com.keyholesoftware.lambda.rest.LanguageResource.listLambdaLanguages()
2018-11-12 07:31:32.004 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[POST]} onto public java.util.List<java.lang.String> com.keyholesoftware.lambda.rest.LanguageResource.postLambdaLanguages(java.lang.String)
2018-11-12 07:31:32.024 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error]} onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-11-12 07:31:32.024 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error],produces=[text/html]} onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-11-12 07:31:32.341 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2aafb23c: startup date [Mon Nov 12 07:31:26 UTC 2018]; root of context hierarchy
2018-11-12 07:31:32.487 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2aafb23c: startup date [Mon Nov 12 07:31:26 UTC 2018]; root of context hierarchy
2018-11-12 07:31:32.727 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : FrameworkServlet dispatcherServlet: initialization completed in 3080 ms
2018-11-12 07:31:32.729 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: characterEncodingFilter to: [/]
2018-11-12 07:31:32.730 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: errorPageFilter to: [/]
2018-11-12 07:31:34.465 INFO 1 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2018-11-12 07:31:34.664 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : Started Application in 9.277 seconds (JVM running for 10.47)
2018-11-12 07:31:34.745 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : 1 Spring WebApplicationInitializers detected on classpath
2018-11-12 07:31:34.746 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : Root context already created (using as parent).

. ____ _ __ _ _
/ / ____ __ _ ()_ __ __ _
( ( )___ | _ | | | _ / _ |
/ )| |)| | | | | || (| | ) ) ) )
|| .__|| ||| |, | / / / /
=========||==============|/=///_/
:: Spring Boot ::

2018-11-12 07:31:34.903 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : The following profiles are active: lambda
2018-11-12 07:31:34.907 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@61d6015a: startup date [Mon Nov 12 07:31:34 UTC 2018]; parent: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2aafb23c
2018-11-12 07:31:35.485 INFO 1 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Overriding bean definition for bean handlerExceptionResolver with a different definition: replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.web.servlet.config.annotation.DelegatingWebMvcConfiguration; factoryMethodName=handlerExceptionResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/web/servlet/config/annotation/DelegatingWebMvcConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=config; factoryMethodName=handlerExceptionResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [com/keyholesoftware/lambda/config/Config.class]]
2018-11-12 07:31:35.648 INFO 1 --- [ main] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 javax.inject.Inject annotation found and supported for autowiring
2018-11-12 07:31:35.687 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext
2018-11-12 07:31:35.687 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 781 ms
2018-11-12 07:31:35.791 INFO 1 --- [ main] o.s.boot.web.servlet.RegistrationBean : Filter errorPageFilter was not registered (possibly already registered?)
2018-11-12 07:31:36.444 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[GET]} onto public java.util.List<com.keyholesoftware.lambda.model.Language> com.keyholesoftware.lambda.rest.LanguageResource.listLambdaLanguages()
2018-11-12 07:31:36.445 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[POST]} onto public java.util.List<java.lang.String> com.keyholesoftware.lambda.rest.LanguageResource.postLambdaLanguages(java.lang.String)
2018-11-12 07:31:36.484 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error]} onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-11-12 07:31:36.509 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error],produces=[text/html]} onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-11-12 07:31:36.869 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@61d6015a: startup date [Mon Nov 12 07:31:34 UTC 2018]; parent: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2aafb23c
2018-11-12 07:31:36.987 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[GET]} onto public java.util.List<com.keyholesoftware.lambda.model.Language> com.keyholesoftware.lambda.rest.LanguageResource.listLambdaLanguages()
2018-11-12 07:31:36.988 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/languages],methods=[POST]} onto public java.util.List<java.lang.String> com.keyholesoftware.lambda.rest.LanguageResource.postLambdaLanguages(java.lang.String)
2018-11-12 07:31:36.991 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error]} onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-11-12 07:31:36.991 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped {[/error],produces=[text/html]} onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-11-12 07:31:37.004 INFO 1 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@61d6015a: startup date [Mon Nov 12 07:31:34 UTC 2018]; parent: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2aafb23c
2018-11-12 07:31:37.409 INFO 1 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2018-11-12 07:31:37.463 INFO 1 --- [ main] com.keyholesoftware.lambda.Application : Started Application in 2.716 seconds (JVM running for 13.269)
2018-11-12 07:31:37.487 ERROR 1 --- [ main] c.a.s.p.i.s.AwsProxyHttpServletRequest : Called set character encoding to UTF-8 on a request without a content type. Character encoding will not be set
2018-11-12 07:31:40.403 INFO 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : 127.0.0.1 - [09/04/2015:12:34:56Z] GET /languages HTTP/1.1 200 2 - Custom User Agent String combined
END RequestId: ee858242-e64c-11e8-b920-f99fde59ed8e
REPORT RequestId: ee858242-e64c-11e8-b920-f99fde59ed8e Duration: 16017.89 ms Billed Duration: 16100 ms Memory Size: 1536 MB Max Memory Used: 172 MB
START RequestId: 94f8f019-e64e-11e8-9f56-1d9b6e5a075d Version: $LATEST
2018-11-12 07:43:01.682 ERROR 1 --- [ main] c.a.s.p.i.s.AwsProxyHttpServletRequest : Called set character encoding to UTF-8 on a request without a content type. Character encoding will not be set
2018-11-12 07:43:02.005 INFO 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : 127.0.0.1 - [09/04/2015:12:34:56Z] GET /languages HTTP/1.1 200 2 - Custom User Agent String combined
END RequestId: 94f8f019-e64e-11e8-9f56-1d9b6e5a075d
REPORT RequestId: 94f8f019-e64e-11e8-9f56-1d9b6e5a075d Duration: 339.08 ms Billed Duration: 400 ms Memory Size: 1536 MB Max Memory Used: 172 MB
START RequestId: 9b5ad976-e64e-11e8-888e-9d1ffac18552 Version: $LATEST
2018-11-12 07:43:12.363 ERROR 1 --- [ main] c.a.s.p.i.s.AwsProxyHttpServletRequest : Called set character encoding to UTF-8 on a request without a content type. Character encoding will not be set
2018-11-12 07:43:12.404 INFO 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : 127.0.0.1 - [09/04/2015:12:34:56Z] GET /languages HTTP/1.1 200 2 - Custom User Agent String combined
END RequestId: 9b5ad976-e64e-11e8-888e-9d1ffac18552
REPORT RequestId: 9b5ad976-e64e-11e8-888e-9d1ffac18552 Duration: 42.93 ms Billed Duration: 100 ms Memory Size: 1536 MB Max Memory Used: 172 MB

The text was updated successfully, but these errors were encountered:

sapessi · 2018-11-12T16:29:10Z

I suspect this could be caused by the fact that SpringBoot automatically discovers the application class while scanning the classpath. Is the application class in the same package as the controllers? I would try and move the application class outside of the controller package so that it's only started by the java container library and spring boot only discovers the controller classes.

DIGIT-SAAS · 2018-11-13T13:07:22Z

I just give that possibility a try and moved the application class in a subpackage. But even that does not help. It simply boots multiple times again in the cloud watch log.

sapessi · 2018-11-13T16:53:09Z

Can we take a look at the spring application class and Lambda handler class?

DIGIT-SAAS · 2018-11-26T08:28:53Z

Sorry for my late response. Here is a clean project where I have the same effect.
StreamLambdaHandler and Spring Application:

public class StreamLambdaHandler implements RequestStreamHandler {
    private static final SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;
    static {
        try {
            handler = SpringBootLambdaContainerHandler.getAwsProxyHandler(Application.class);
        } catch (ContainerInitializationException e) {
            e.printStackTrace();
            throw new RuntimeException("Could not initialize Spring Boot application", e);
        }
    }
    @Override
    public void handleRequest(InputStream inputStream, OutputStream outputStream, Context context)
            throws IOException {
        handler.proxyStream(inputStream, outputStream, context);
    }
}

@SpringBootApplication
// We use direct @Import instead of @ComponentScan to speed up cold starts
@Import({ PingController.class, DynamoDBConfig.class })
public class Application extends SpringBootServletInitializer {

    @Bean
    public HandlerMapping handlerMapping() {
        return new RequestMappingHandlerMapping();
    }

    @Bean
    public HandlerAdapter handlerAdapter() {
        return new RequestMappingHandlerAdapter();
    }

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }
}

jorgetravieso · 2018-11-26T20:15:11Z

I am having a similar issue, the application context is loaded again. On my local machine, the cold start is about 6 seconds. But when it's deployed to AWS, it's taking 30 plus seconds which leads to timeouts.

In my case, the lambda function is connecting to RDS (Aurora) so it's probably creating a network interface. This is a big limitation of lambda, IMO.

sapessi · 2018-11-26T21:23:58Z

Thanks @DIGIT-SAAS, can you share the package structure too? Are the StreamLambdaHandler and Application in the same package?

DIGIT-SAAS · 2018-11-27T09:12:01Z

@sapessi I can share it privately if this would help? I created an maven archetype so you can create new projects with this settings... The main problem is the one @jtraviesor stated: It takes more than 45 Seconds to fire up this function on AWS..

sapessi · 2018-11-29T06:56:09Z

Hey @DIGIT-SAAS, apologies for the delay. re:Invent is taking all of my attention. I don't need to have exact names. What's interesting to me is whether the StreamHandler is in the same package as the Application class, feel free to call them foo.bar in the example - structure is more important than names.

DIGIT-SAAS · 2018-11-29T08:02:19Z

I moved the Application class into a subpackage e.g. the folder structure looks like this:

| - StreamLambdaHandler.java
| + config
  | - SpringConfig.java
  | - DynamoDBConfig.java
| + controller
  | - PingController.java
  | - Application.java
| + model
  | + pojo
    | - Language.java
  | + repositories
    | - LanguageRepo.java

sapessi · 2018-12-01T18:49:35Z

Assume after you moved the config and application into a sub-package the behavior is still the same? I'll try to replicate next week.

DIGIT-SAAS · 2019-01-10T14:53:37Z

Did you have some luck? We tested it in multiple scenarios and it takes round about 45 seconds to call one function... this is nearly unusable....

sapessi · 2019-01-10T17:57:59Z

I've been trying to replicate. Are you including other spring boot starter projects as dependencies. I suspect that may be the cause.

grsterin · 2019-01-11T15:00:37Z

I have the same issue and I think I may have found a workaround for it. I just removed SpringBootLambdaContainerHandler's initialization from static block into handleRequest method with if(handler == null) condition, and made the field non-static. That seems to solve the problem.

public class StreamLambdaHandler implements RequestStreamHandler {
    private SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;

    public void handleRequest(InputStream inputStream, OutputStream outputStream, Context context)
            throws IOException {
        if (handler == null) {
            try {
                handler = SpringBootLambdaContainerHandler.getAwsProxyHandler(Application.class);
            } catch (ContainerInitializationException e) {
                e.printStackTrace();
                throw new RuntimeException("Could not initialize Spring Boot application", e);
            }
        }
        handler.proxyStream(inputStream, outputStream, context);
    }
}

sapessi · 2019-01-11T16:38:03Z

Interesting, thanks for the tip @grsterin. I'd like to get to the bottom of why that is happening because using the static variable gives you a considerable boost in performance. I'll keep digging into it.

Noisyfox · 2019-02-26T06:57:17Z

Seems that if the static init took > than 10 seconds, then the handler instance will be killed by aws, and then it will re-init the handler again within a START-END-REPORT which means you have to pay for the init time. If your init completes within 10 seconds then that init time is free.

sapessi · 2019-06-27T22:30:46Z

Moving this to release 1.4 - planning to work on an async initializer to make the most of the 10 seconds and then switch to the handler.

and #234. Also added a new builder object that makes it easier to construct container handlers

sapessi · 2019-09-26T04:59:08Z

Hi @DIGIT-SAAS, @Noisyfox, @grsterin, @jtraviesor - For the series "better late than never", I have finally found the time to work on the async init. You can test it in the 1.4-SNAPSHOT release from the core branch of this repo: git clone the repo, git checkout core, then mvn install on your local box. Note that if you are using Spring Boot 2.x we have broken out support into a separate package: aws-serverless-java-container-springboot2.

You can now construct a handler that starts asynchronously this way:

public class LambdaHandler implements RequestHandler<AwsProxyRequest, AwsProxyResponse> {
    private SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;
    public LambdaHandler() {
        try {
            long startTime = Instant.now().toEpochMilli();
            handler = new SpringBootProxyHandlerBuilder()
                    .defaultProxy()
                    .asyncInit(startTime)
                    .springBootApplication(SlowTestApplication.class)
                    .buildAndInitialize();
        } catch (ContainerInitializationException e) {
            e.printStackTrace();
        }
    }

    @Override
    public AwsProxyResponse handleRequest(AwsProxyRequest awsProxyRequest, Context context) {
        return handler.proxy(awsProxyRequest, context);
    }
}

kartoffelsup · 2019-09-27T11:38:40Z

Thanks for the fix :) We are having the same issue with the regular spring container (no spring-boot) will this also fix it there?

… use the asyn initialization wrapper (#210)

sapessi · 2019-09-27T15:35:43Z

Yes @kartoffelsup, it works with the spring package too. I've added Builder objects for both plain spring and springboot 1.x. I've also added a unit test to triple-check that the async initialization wrapper works with those frameworks too.

sapessi · 2019-09-30T15:32:45Z

Release 1.4 is out on maven central. The release notes include a list of all the changes. Closing this issue.

kartoffelsup · 2019-10-01T08:21:23Z

Hi @sapessi,
just tested this and the AsyncInitializationWrapper returns immediately when using the SpringProxyHandlerBuilder. So no real initialization happens asynchronously. Only after actually calling handler.proxy, the Servlet gets initalized in AwsServletRegistration:

    public Servlet getServlet() throws ServletException {
        if (servlet.getServletConfig() == null) {
            servlet.init(getServletConfig());
        }
        return servlet;
    }

I added an extra log statement for testing:

 @Override
        @SuppressFBWarnings("DM_EXIT")
        public void run() {
            log.info("Starting async initializer");
            try {
                handler.initialize();
                log.info("Initialized");
            } catch (ContainerInitializationException e) {
                log.error("Failed to initialize container handler", e);
                // we cannot return the exception so we crash the whole kaboodle here
                System.exit(1);
            }
            synchronized(this) {
                initLatch.countDown();
            }
        }

2019-10-01 10:10:48  INFO  LambdaContainerHandler:100 - Starting Lambda Container Handler
2019-10-01 10:10:48  INFO  AsyncInitializationWrapper:54 - Async initialization will wait for 9185ms
2019-10-01 10:10:48  INFO  AsyncInitializationWrapper:90 - Starting async initializer
2019-10-01 10:10:48  INFO  AsyncInitializationWrapper:93 - Initialized

sapessi · 2019-10-01T17:03:35Z

Hey @kartoffelsup can you share the full code. I've added a slow app unit test for Spring too and it seems to work there.

kartoffelsup · 2019-10-01T17:09:30Z

The test hast the same issue:

[main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler
[main] INFO com.amazonaws.serverless.proxy.AsyncInitializationWrapper - Async initialization will wait for 9176ms
[Thread-0] INFO com.amazonaws.serverless.proxy.AsyncInitializationWrapper - Starting async initializer
Start time: 594
[main] INFO com.amazonaws.serverless.proxy.internal.servlet.AwsServletContext - Initializing Spring DispatcherServlet 'dispatcherServlet'
[main] INFO org.springframework.web.servlet.DispatcherServlet - Initializing Servlet 'dispatcherServlet'
Okt 01, 2019 7:08:19 PM org.hibernate.validator.internal.util.Version <clinit>
INFO: HV000001: Hibernate Validator 5.4.1.Final
[main] INFO org.springframework.web.servlet.DispatcherServlet - Completed initialization in 13570 ms
[main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - 127.0.0.1 - [01/10/2019:17:08:06+0200] "GET /hello HTTP/1.1" 200 5 "-" "-" combined

Spring context initialization starts after async initialization, during request execution.

sapessi · 2019-10-01T17:34:48Z

You are right @kartoffelsup - I think it my be because the init() method on servlets is called when a request arrives, not when the servlet is loaded. Looking at the specs there is no clear answer on this so I think it should be fine to move the init() call to the initialize() method of the container handler:

After the servlet object is instantiated, the container must initialize the servlet before
it can handle requests from clients.

I'll explore making this change and testing it for a patch release soon. Thanks again for doing all the digging.

guidogio · 2020-03-06T16:00:22Z

Sorry, I re-open this topic.

I've the same problem. Spring load multiple time and finally not start. i've implemented the asyn handler but not work.

Spring boot 2.x
Spring boot JPA

jkhalid · 2020-03-18T15:50:06Z

@sapessi Thank you so much. The static block is really a performance boost.
@guidogio . This might help you out
public class LambdaFunctionHandler implements RequestHandler<AwsProxyRequest, AwsProxyResponse> { private static SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler; static { try { long startTime = Instant.now().toEpochMilli(); handler = new SpringBootProxyHandlerBuilder() .defaultProxy() .asyncInit(startTime) .springBootApplication(Application.class) .profiles(ofNullable(System.getenv("ENVIRONMENT")).orElse("dev")) .buildAndInitialize(); long endTime = Instant.now().toEpochMilli(); System.out.println("Lambda initialization time is "+(endTime-startTime)); } catch (ContainerInitializationException e) { e.printStackTrace(); throw new RuntimeException("Could not initialize Spring Boot application", e); } } @Override public AwsProxyResponse handleRequest(AwsProxyRequest awsProxyRequest, Context context) { return handler.proxy(awsProxyRequest, context); } }

Also please make sure you have the right maven dependency in the pom file.
 <dependency> <groupId>com.amazonaws.serverless</groupId> <artifactId>aws-serverless-java-container-springboot2</artifactId> <version>1.4</version> </dependency>

lunarwtr · 2023-05-19T18:34:42Z

I realize this ticket is closed, but is there a new one tracking the fact it still happens?

Spring boot 2.x
Spring boot JPA

deki · 2023-05-19T18:39:09Z

@lunarwtr please open a new ticket, ideally with a small sample that reproduces the issue. Thanks!

sapessi added the help wanted label Jan 11, 2019

shuangy92 mentioned this issue Feb 1, 2019

ExceptionInInitializerError when using spring with profile #234

Closed

sapessi added the enhancement label Jun 27, 2019

sapessi added this to the Release 1.4 milestone Jun 27, 2019

sapessi mentioned this issue Sep 24, 2019

NPE with AWS Lambda and API Gateway #281

Closed

sapessi added a commit that referenced this issue Sep 26, 2019

Added new InitializationWrapper and Async implementation to address #210

301f718

and #234. Also added a new builder object that makes it easier to construct container handlers

sapessi mentioned this issue Sep 26, 2019

SAM local building response properly, but Internal Server Error when deployed #264

Closed

sapessi added a commit that referenced this issue Sep 27, 2019

Added slow init tests for Spring and SpringBoot 1.x applications that…

ae6fd4f

… use the asyn initialization wrapper (#210)

sapessi closed this as completed Sep 30, 2019

This was referenced Oct 1, 2019

Initialize Servlets at construction - in the initialize() method #287

Closed

NPE with AWS Lambda and SpringBoot starting multiple times #291

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Spring Boot Lambda Startup multiple times #210

Spring Boot Lambda Startup multiple times #210

DIGIT-SAAS commented Nov 12, 2018

sapessi commented Nov 12, 2018

DIGIT-SAAS commented Nov 13, 2018

sapessi commented Nov 13, 2018

DIGIT-SAAS commented Nov 26, 2018

jorgetravieso commented Nov 26, 2018

sapessi commented Nov 26, 2018

DIGIT-SAAS commented Nov 27, 2018

sapessi commented Nov 29, 2018

DIGIT-SAAS commented Nov 29, 2018

sapessi commented Dec 1, 2018

DIGIT-SAAS commented Jan 10, 2019

sapessi commented Jan 10, 2019

grsterin commented Jan 11, 2019 •

edited

Loading

sapessi commented Jan 11, 2019

Noisyfox commented Feb 26, 2019

sapessi commented Jun 27, 2019

sapessi commented Sep 26, 2019

kartoffelsup commented Sep 27, 2019

sapessi commented Sep 27, 2019

sapessi commented Sep 30, 2019

kartoffelsup commented Oct 1, 2019

sapessi commented Oct 1, 2019

kartoffelsup commented Oct 1, 2019 •

edited

Loading

sapessi commented Oct 1, 2019

guidogio commented Mar 6, 2020 •

edited

Loading

jkhalid commented Mar 18, 2020

lunarwtr commented May 19, 2023

deki commented May 19, 2023

Spring Boot Lambda Startup multiple times #210

Spring Boot Lambda Startup multiple times #210

Comments

DIGIT-SAAS commented Nov 12, 2018

Scenario

Expected behavior

Actual behavior

Steps to reproduce

Question

Full log output

sapessi commented Nov 12, 2018

DIGIT-SAAS commented Nov 13, 2018

sapessi commented Nov 13, 2018

DIGIT-SAAS commented Nov 26, 2018

jorgetravieso commented Nov 26, 2018

sapessi commented Nov 26, 2018

DIGIT-SAAS commented Nov 27, 2018

sapessi commented Nov 29, 2018

DIGIT-SAAS commented Nov 29, 2018

sapessi commented Dec 1, 2018

DIGIT-SAAS commented Jan 10, 2019

sapessi commented Jan 10, 2019

grsterin commented Jan 11, 2019 • edited Loading

sapessi commented Jan 11, 2019

Noisyfox commented Feb 26, 2019

sapessi commented Jun 27, 2019

sapessi commented Sep 26, 2019

kartoffelsup commented Sep 27, 2019

sapessi commented Sep 27, 2019

sapessi commented Sep 30, 2019

kartoffelsup commented Oct 1, 2019

sapessi commented Oct 1, 2019

kartoffelsup commented Oct 1, 2019 • edited Loading

sapessi commented Oct 1, 2019

guidogio commented Mar 6, 2020 • edited Loading

jkhalid commented Mar 18, 2020

lunarwtr commented May 19, 2023

deki commented May 19, 2023

grsterin commented Jan 11, 2019 •

edited

Loading

kartoffelsup commented Oct 1, 2019 •

edited

Loading

guidogio commented Mar 6, 2020 •

edited

Loading