Spring Boot Lambda Startup multiple times

[DIGIT-SAAS]

• 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

1. 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
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

[sapessi]

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]

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]

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

[DIGIT-SAAS]

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]

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]

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

[DIGIT-SAAS]

@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]

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]

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]

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]

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]

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

[grsterin]

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]

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.