Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AWS Lambda - Repeated initialization sequence in log #1030

Closed
schlumpfling42 opened this issue May 3, 2023 · 5 comments
Closed

AWS Lambda - Repeated initialization sequence in log #1030

schlumpfling42 opened this issue May 3, 2023 · 5 comments
Assignees
Milestone

Comments

@schlumpfling42
Copy link

schlumpfling42 commented May 3, 2023

I got my function deployed to AWS and it's running fine, but I'm worried about seeing the init sequence 2 times in the log (I have seen it 3 times when it fails) and long (probably double) boot up time:

INIT_START Runtime Version: java:17.v7	Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:96e2d0d0bee4fffca3fa35b8b6b1bac511e2f4303249cbf813a774543df2b5b0
--
22:39:28.683 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-core-1.2.2.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Archiver-Version: Plexus Archiver
Created-By: Apache Maven
Built-By: andclt
Build-Jdk: 1.8.0_342
22:39:28.693 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-runtime-interface-client-2.3.1.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Implementation-Title: AWS Lambda Java Runtime Interface Client
Implementation-Version: 2.3.1
Class-Path: aws-lambda-java-core-1.2.2.jar aws-lambda-java-serialization
-1.1.2.jar
Build-Jdk-Spec: 1.8
Created-By: Maven JAR Plugin 3.3.0
Main-Class: com.amazonaws.services.lambda.runtime.api.client.AWSLambda
22:39:28.712 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-serialization-1.1.2.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Archiver-Version: Plexus Archiver
Built-By: smirnoal
Created-By: Apache Maven 3.8.6
Build-Jdk: 1.8.0_352
22:39:28.713 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/Log4jHotPatch.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Premain-Class: Log4jHotPatch17
Agent-Class: Log4jHotPatch17
Can-Redefine-Classes: true
Can-Retransform-Classes: true
Created-by: Amazon OpenJDK Team
Main-Class: Log4jHotPatch17
22:39:28.714 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: file:/var/task/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Main-Class: net.test.FunctionsApplication
22:39:28.744 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Loaded Start Class: class net.test.FunctionsApplication
22:39:28.744 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Main class: class net.test.FunctionsApplication
.   ____          _            __ _ _
/\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ \| '_ \| '_\| \| '_ \/ _` \| \ \ \ \
\\/  ___)\| \|_)\| \| \| \| \| \|\| (_\| \|  ) ) ) )
'  \|____\| .__\|_\| \|_\|_\| \|_\__, \| / / / /
=========\|_\|==============\|___/=/_/_/_/
:: Spring Boot ::                (v3.0.5)
2023-05-03 22:39:31-867 [main] INFO  o.s.c.f.a.a.CustomRuntimeInitializer - AWS Handler: org.springframework.cloud.function.adapter.aws.FunctionInvoker
2023-05-03 22:39:33-130 [main] INFO  o.s.d.r.c.RepositoryConfigurationDelegate - Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2023-05-03 22:39:33-389 [main] INFO  o.s.d.r.c.RepositoryConfigurationDelegate - Finished Spring Data repository scanning in 241 ms. Found 1 JPA repository interfaces.
2023-05-03 22:39:33-861 [main] INFO  o.s.cloud.context.scope.GenericScope - BeanFactory id=95d09f5f-3a1b-3acd-805b-e07da9f5285d
2023-05-03 22:39:34-128 [main] DEBUG com.zaxxer.hikari.HikariConfig - Driver class org.postgresql.Driver found in Thread context class loader com.amazonaws.services.lambda.runtime.api.client.CustomerClassLoader@6e8cf4c6
22:39:39.503 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-core-1.2.2.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
--
Archiver-Version: Plexus Archiver
Created-By: Apache Maven
Built-By: andclt
Build-Jdk: 1.8.0_342
22:39:39.524 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-runtime-interface-client-2.3.1.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Implementation-Title: AWS Lambda Java Runtime Interface Client
Implementation-Version: 2.3.1
Class-Path: aws-lambda-java-core-1.2.2.jar aws-lambda-java-serialization
-1.1.2.jar
Build-Jdk-Spec: 1.8
Created-By: Maven JAR Plugin 3.3.0
Main-Class: com.amazonaws.services.lambda.runtime.api.client.AWSLambda
22:39:39.622 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-serialization-1.1.2.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Archiver-Version: Plexus Archiver
Built-By: smirnoal
Created-By: Apache Maven 3.8.6
Build-Jdk: 1.8.0_352
22:39:39.623 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/Log4jHotPatch.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Premain-Class: Log4jHotPatch17
Agent-Class: Log4jHotPatch17
Can-Redefine-Classes: true
Can-Retransform-Classes: true
Created-by: Amazon OpenJDK Team
Main-Class: Log4jHotPatch17
22:39:39.640 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: file:/var/task/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Main-Class: net.test.FunctionsApplication
22:39:39.741 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Loaded Start Class: class net.test.FunctionsApplication
22:39:39.741 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Main class: class net.test.FunctionsApplication
.   ____          _            __ _ _
/\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ \| '_ \| '_\| \| '_ \/ _` \| \ \ \ \
\\/  ___)\| \|_)\| \| \| \| \| \|\| (_\| \|  ) ) ) )
'  \|____\| .__\|_\| \|_\|_\| \|_\__, \| / / / /
=========\|_\|==============\|___/=/_/_/_/
:: Spring Boot ::                (v3.0.5)
2023-05-03 22:39:50-762 [main] INFO  o.s.c.f.a.a.CustomRuntimeInitializer - AWS Handler: org.springframework.cloud.function.adapter.aws.FunctionInvoker
2023-05-03 22:39:55-425 [main] INFO  o.s.d.r.c.RepositoryConfigurationDelegate - Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2023-05-03 22:39:56-340 [main] INFO  o.s.d.r.c.RepositoryConfigurationDelegate - Finished Spring Data repository scanning in 842 ms. Found 1 JPA repository interfaces.
2023-05-03 22:39:58-142 [main] INFO  o.s.cloud.context.scope.GenericScope - BeanFactory id=95d09f5f-3a1b-3acd-805b-e07da9f5285d
2023-05-03 22:39:59-164 [main] DEBUG com.zaxxer.hikari.HikariConfig - Driver class org.postgresql.Driver found in Thread context class loader com.amazonaws.services.lambda.runtime.api.client.CustomerClassLoader@6e8cf4c6
...<application logs>

I am using Cloud Function version 4.0.2 and boot version 3.0.5.

I think it has to do with me trying to import configuration from secrets manager and parameter store:

    implementation 'io.awspring.cloud:spring-cloud-starter-aws-secrets-manager-config:2.4.4'
    implementation 'io.awspring.cloud:spring-cloud-starter-aws-parameter-store-config:2.4.4'

The app first starts up with the parameters provided in the properties file and get initialized later with the configuration from the secrets manager / parameter store.
I have some dummy values for the database configuration in the applications.properties. If I take those out the app will fail initializing, as a matter of fact it will fail twice.

I will try reproducing the problem locally and post an update in here.

@schlumpfling42
Copy link
Author

After a series of tests I figured out that I had another configuration problem and I am not certain the issue has something to do with the secrets manager/parameter store.
I don't have the issue locally, only the deployed lambda is reinitializing. I will turn up the log level to debug and see if there is anything in the logs to figure out whats wrong. Other than that I'm out of ideas.

@schlumpfling42
Copy link
Author

Here is the debug output right when it re-initializes:

2023-05-04 16:03:31-681 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.config.internalBeanConfigurerAspect'
--
2023-05-04 16:03:31-684 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'postgresEntityManagerFactory'
2023-05-04 16:03:31-684 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'postgresJpaConfiguration'
2023-05-04 16:03:31-686 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'entityManagerFactoryBuilder'
2023-05-04 16:03:31-687 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration'
2023-05-04 16:03:31-692 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'spring.jpa-org.springframework.boot.autoconfigure.orm.jpa.JpaProperties'
2023-05-04 16:03:31-695 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'spring.jpa.hibernate-org.springframework.boot.autoconfigure.orm.jpa.HibernateProperties'
2023-05-04 16:03:31-696 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration' via constructor to bean named 'postgresDataSource'
2023-05-04 16:03:31-696 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration' via constructor to bean named 'spring.jpa-org.springframework.boot.autoconfigure.orm.jpa.JpaProperties'
2023-05-04 16:03:31-697 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration' via constructor to bean named 'org.springframework.beans.factory.support.DefaultListableBeanFactory@5e39850'
2023-05-04 16:03:31-697 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.boot.autoconfigure.orm.jpa.HibernateJpaConfiguration' via constructor to bean named 'spring.jpa.hibernate-org.springframework.boot.autoconfigure.orm.jpa.HibernateProperties'
2023-05-04 16:03:31-699 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'hikariPoolDataSourceMetadataProvider'
2023-05-04 16:03:31-699 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.jdbc.metadata.DataSourcePoolMetadataProvidersConfiguration$HikariPoolDataSourceMetadataProviderConfiguration'
2023-05-04 16:03:31-705 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Creating shared instance of singleton bean 'jpaVendorAdapter'
2023-05-04 16:03:31-733 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'entityManagerFactoryBuilder' via factory method to bean named 'jpaVendorAdapter'
2023-05-04 16:03:31-736 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'postgresEntityManagerFactory' via factory method to bean named 'postgresDataSource'
2023-05-04 16:03:31-737 [main] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'postgresEntityManagerFactory' via factory method to bean named 'entityManagerFactoryBuilder'
2023-05-04 16:03:31-774 [main] DEBUG o.s.o.j.LocalContainerEntityManagerFactoryBean - Building JPA container EntityManagerFactory for persistence unit 'default'
16:03:36.037 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-core-1.2.2.jar!/META-INF/MANIFEST.MF
Manifest-Version: 1.0
Archiver-Version: Plexus Archiver
Created-By: Apache Maven
Built-By: andclt
Build-Jdk: 1.8.0_342
16:03:36.074 [main] INFO org.springframework.cloud.function.utils.FunctionClassUtils -- Searching for start class in manifest: jar:file:/var/runtime/lib/aws-lambda-java-runtime-interface-client-2.3.1.jar!/META-INF/MANIFEST.MF
...

@schlumpfling42
Copy link
Author

OK, I found the issue. AWSLambda the launcher that is used by AWS is creating 2 instances of org.springframework.cloud.function.adapter.aws.FunctionInvoker one without event name and one with the event name.
The invoker has the startup in the constructor, so it's started up twice.
I created a wrapper for the invoker that is creating the instance of FunctionInvoker when handleRequest is called.

@olegz olegz closed this as completed in 1395424 May 24, 2023
@olegz
Copy link
Contributor

olegz commented May 24, 2023

I added the FUNCTION_INVOKER_LATE_INITIALIZATION flag. You can now set it to true in the AWS Environment and the initialisation will be deferred to first request

@olegz olegz added the AWS label May 24, 2023
@olegz olegz added this to the 4.0.3 milestone May 24, 2023
@olegz olegz self-assigned this May 24, 2023
@michaelcordero
Copy link

michaelcordero commented Nov 28, 2023

Hi Oleg, is there any plans on fixing this another way, without defining an environment variable, or will this be the official solution going forward?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants