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

NPE with AWS Lambda and SpringBoot starting multiple times #291

Closed
MounicaRamini opened this issue Oct 8, 2019 · 10 comments
Closed

NPE with AWS Lambda and SpringBoot starting multiple times #291

MounicaRamini opened this issue Oct 8, 2019 · 10 comments

Comments

@MounicaRamini
Copy link

MounicaRamini commented Oct 8, 2019

Framework version: XX
Implementations: Spring Boot / Lambda

Scenario
NPE when invoking Lambda Function in AWS Lambda Console and Spring Boot starting multiple times

Expected behavior
Should be inserting and fetching records from database when Lambda is invoked

Actual behavior
Throws below error, when Lambda is executed by using AWS Lambda Test Events

Full log output
Error Message on AWS Lambda Cosole :

{
  "statusCode": 404,
  "multiValueHeaders": {
    "Content-Type": [
      "application/json;charset=UTF-8"
    ]
  },
  "body": "{\"timestamp\":\"2019-10-08T13:49:39.550+0000\",\"status\":404,\"error\":\"Not Found\",\"message\":\"No message available\",\"path\":\"/loggingServiceAPI/viewLogs\"}",
  "isBase64Encoded": false
}

Full log output on Cloud Watch

06:15:38.615 [main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler
06:15:39.071 [main] INFO com.amazonaws.serverless.proxy.internal.servlet.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath
2019-10-08 06:15:42.633 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$c65caf6b] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

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

2019-10-08 06:15:45.072 INFO 1 --- [ main] c.d.lambda.Configuration.AwsSsmConfig : Retrieving configuration details from AWS parameter store
2019-10-08 06:15:46.510 INFO 1 --- [ main] c.d.lambda.Configuration.AwsSsmConfig : Found jdf-recordretention-ndl-devl-appid SecureString
2019-10-08 06:15:46.527 INFO 1 --- [ main] c.d.lambda.Configuration.AwsSsmConfig : Found jdf-recordretention-ndl-devl-password SecureString
2019-10-08 06:15:46.527 INFO 1 --- [ main] b.c.PropertySourceBootstrapConfiguration : Located property source: MapPropertySource {name='aws-ssm'}
2019-10-08 06:15:46.594 INFO 1 --- [ main] com.deere.lambda.LoggingServiceConfig : No active profile set, falling back to default profiles: default
START RequestId: 4c27b1a6-b153-4fa0-aa78-6cb612f4819a Version: $LATEST
06:15:49.529 [main] INFO com.amazonaws.serverless.proxy.internal.LambdaContainerHandler - Starting Lambda Container Handler
06:15:50.451 [main] INFO com.amazonaws.serverless.proxy.internal.servlet.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath
2019-10-08 06:15:57.291 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$c83c3ffd] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

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

2019-10-08 06:16:02.070 INFO 1 --- [ main] c.d.lambda.Configuration.AwsSsmConfig : Retrieving configuration details from AWS parameter store
2019-10-08 06:16:04.768 INFO 1 --- [ main] c.d.lambda.Configuration.AwsSsmConfig : Found jdf-recordretention-ndl-devl-appid SecureString
2019-10-08 06:16:04.769 INFO 1 --- [ main] c.d.lambda.Configuration.AwsSsmConfig : Found jdf-recordretention-ndl-devl-password SecureString
2019-10-08 06:16:04.769 INFO 1 --- [ main] b.c.PropertySourceBootstrapConfiguration : Located property source: MapPropertySource {name='aws-ssm'}
2019-10-08 06:16:04.868 INFO 1 --- [ main] com.deere.lambda.LoggingServiceConfig : No active profile set, falling back to default profiles: default
2019-10-08 06:16:08.588 INFO 1 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in DEFAULT mode.
2019-10-08 06:16:09.254 INFO 1 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 566ms. Found 1 repository interfaces.
2019-10-08 06:16:12.111 INFO 1 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=3039cc2d-19a8-3ae1-855a-155f642fa6d3
2019-10-08 06:16:13.147 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$ac223d00] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-08 06:16:13.372 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$c83c3ffd] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-08 06:16:13.391 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext
2019-10-08 06:16:13.391 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 8461 ms
2019-10-08 06:16:15.189 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-10-08 06:16:15.189 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2019-10-08 06:16:16.810 WARN 1 --- [ main] aWebConfiguration$JpaWebMvcConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2019-10-08 06:16:18.828 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2019-10-08 06:16:19.729 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2019-10-08 06:16:20.432 INFO 1 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [
name: default
...]
2019-10-08 06:16:20.987 INFO 1 --- [ main] org.hibernate.Version : HHH000412: Hibernate Core {[WORKING]}
2019-10-08 06:16:20.990 INFO 1 --- [ main] org.hibernate.cfg.Environment : HHH000206: hibernate.properties not found
2019-10-08 06:16:21.654 INFO 1 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.0.4.Final}
2019-10-08 06:16:30.290 INFO 1 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect
2019-10-08 06:16:30.793 INFO 1 --- [ main] o.h.e.j.e.i.LobCreatorBuilderImpl : HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
2019-10-08 06:16:30.810 INFO 1 --- [ main] org.hibernate.type.BasicTypeRegistry : HHH000270: Type registration [java.util.UUID] overrides previous : org.hibernate.type.UUIDBinaryType@331acdad
2019-10-08 06:16:32.392 INFO 1 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2019-10-08 06:16:36.413 INFO 1 --- [ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService 'applicationTaskExecutor'
2019-10-08 06:16:36.668 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 21479 ms
2019-10-08 06:16:38.787 INFO 1 --- [ main] com.deere.lambda.LoggingServiceConfig : Started LoggingServiceConfig in 47.663 seconds (JVM running for 50.756)
2019-10-08 06:16:38.854 ERROR 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : Error while handling request

java.lang.NullPointerException: null
at com.amazonaws.serverless.proxy.internal.servlet.AwsProxyHttpServletRequestReader.readRequest(AwsProxyHttpServletRequestReader.java:48)
at com.amazonaws.serverless.proxy.internal.servlet.AwsProxyHttpServletRequestReader.readRequest(AwsProxyHttpServletRequestReader.java:28)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxy(LambdaContainerHandler.java:174)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxyStream(LambdaContainerHandler.java:209)
at com.deere.lambda.LambdaHandler.LoggingServiceLambdaHandler.handleRequest(LoggingServiceLambdaHandler.java:30)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

AWS POM Dependencies

 <dependency>
            <groupId>com.amazonaws</groupId>
            <artifactId>aws-lambda-java-core</artifactId>
            <version>1.2.0</version>
        </dependency>

        <dependency>
            <groupId>com.amazonaws.serverless</groupId>
            <artifactId>aws-serverless-java-container-spring</artifactId>
            <version>1.3</version>
        </dependency>

SpringBoot Lambda Handler Class

public class LambdaHandler implements RequestHandler<AwsProxyRequest, AwsProxyResponse> {

    private static SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;

    static {
        try {
            handler = SpringBootLambdaContainerHandler.getAwsProxyHandler(SpringBootApplication.class);
        } catch (ContainerInitializationException e) {
            // if we fail here. We re-throw the exception to force another cold start
            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);
    }
}

Application class

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

Test Data in JSON for LAMBDA-PROXY event. Is there any other Test Event format that I can use to test AWS Lambda Function on AWS Lambda Console

{
  "resource": "/path/resource",
  "path": "/path/resource",
  "httpMethod": "POST",
  "headers": {
      "Accept" : "application/json",
       "content-type": "application/json"
  }
  "multiValueHeaders": {},
  "queryStringParameters": null,
  "multiValueQueryStringParameters": null,
  "pathParameters": null,
  "stageVariables": null,
  "requestContext": {
    "resourcePath": "/path/resource",
    "httpMethod": "POST",
    "path": "//path/resource",
    "accountId": "accountIdNumber",
    "protocol": "HTTP/1.1",
    "stage": "test-invoke-stage",
    "domainPrefix": "testPrefix",
    "identity": {
      "cognitoIdentityPoolId": null,
      "cognitoIdentityId": null,
      "apiKey": "test-invoke-api-key",
      "principalOrgId": null,
      "cognitoAuthenticationType": null,
      "userArn": "actual arn with my userid",
      "apiKeyId": "test-invoke-api-key-id"
    }
  },
  "body": "{ \"Key1\": \"Value1\", \"Key2\": \"Value2\", \"Key3\": \"Vaue3\" }",
  "isBase64Encoded": "false"
}

This message also displays on CloudWatch, despite of giving headers

2019-10-08 14:38:44.255 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
2019-10-08 14:38:44.279  INFO 1 --- [           main] c.a.s.p.internal.LambdaContainerHandler  : null arn value [01/01/1970:00:00:00Z] "POST /error HTTP/1.1" 404 147 "-" "-" combined
END RequestId: 6b16c329-d34a-446c-bfbc-03cdce672731

@sapessi Can you please help me with this issue

@sapessi
Copy link
Collaborator

sapessi commented Oct 8, 2019

Hi @MounicaRamini, couple of things that could be going on:

  1. For the NPE, can you switch to the latest version of the framework (1.4). For Spring Boot 1.5.x use aws-serverless-java-container-spring. For Spring Boot 2.x use aws-serverless-java-container-springboot2
  2. For the multiple starts, you may be running afoul of the 10 seconds init timeout (see issue Spring Boot Lambda Startup multiple times #210). This was also solved in the latest release of the framework with the new asynchronous initialization.

Hope this helps.

@MounicaRamini
Copy link
Author

@sapessi What does the below error mean ?

2019-10-08 14:38:44.279 INFO 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : null arn value

The arn value had assumed role with my empid at the end. Does that mean, am not allowed to perform anything there ? What does null mean here ?

@sapessi
Copy link
Collaborator

sapessi commented Oct 8, 2019

It's not an error, just an INFO log. Having said that, I can't seem to find that log line anywhere in the code. Can you share a few log lines around it?

@MounicaRamini
Copy link
Author

MounicaRamini commented Oct 8, 2019

Hi @sapessi I haven't added anywhere in the code to log that INFO. It must be from internal jars. I have taken that request format while triggering API Gateway, and started to test it out in AWS Lambda Console to check the solution because of API timeout issues.

Also, at the end of errors, I see it forming an endpoint in the format "POST /path/resourceHTTP/1.1", Is is correct ?

START RequestId: 0c87477e-334e-4722-a402-ccb142a4b794 Version: $LATEST
2019-10-08 17:34:32.450  INFO 1 --- [           main] c.a.s.p.internal.LambdaContainerHandler  : null - [08/10/2019:17:34:32Z] "POST /path/resourceHTTP/1.1" 404 - "-" "-" combined
END RequestId: 0c87477e-334e-4722-a402-ccb142a4b794

But on API gateway, the way endpoint is /path/resource
So, just curious if it's hitting the correct endpoint, because I see below error where body is empty and response is 404

{
  "statusCode": 404,
  "multiValueHeaders": {},
  "body": "",
  "isBase64Encoded": false
}

@sapessi
Copy link
Collaborator

sapessi commented Oct 8, 2019

The first null in the log line is because your test event does not include a remote address. The path being merged with the protocol is definitely funky, there is clearly a space between the two in the log formatter. Can you make sure you don't have bad characters in the path you are passing in through the test event? Perhaps re-type it in manually.

@MounicaRamini
Copy link
Author

Could you please share me a sample event to test please

@sapessi
Copy link
Collaborator

sapessi commented Oct 8, 2019

It should look something like this (make sure to adjust path/method/headers to something that suites your app):

{
    "resource":"/helloworld",
    "path":"/helloworld",
    "httpMethod":"GET",
    "headers": {
        "Accept":"*/*",
        "content-type":"application/json",
        "Host":"r275xc9bmd.execute-api.us-east-1.amazonaws.com",
        "User-Agent":"curl/7.64.0",
        "X-Amzn-Trace-Id":"Root=1-1a2b3c4d-a1b2c3d4e5f6a1b2c3d4e5f6",
        "X-Forwarded-For":"72.21.198.64",
        "X-Forwarded-Port":"443",
        "X-Forwarded-Proto":"https"
    },
    "multiValueHeaders":{
        "Accept":["*/*"],
        "content-type":["application/json"],
        "Host":["r275xc9bmd.execute-api.us-east-1.amazonaws.com"],
        "User-Agent":["curl/0.0.0"],
        "X-Amzn-Trace-Id":["Root=1-1a2b3c4d-a1b2c3d4e5f6a1b2c3d4e5f6"],
        "X-Forwarded-For":["11.22.333.44"],
        "X-Forwarded-Port":["443"],
        "X-Forwarded-Proto":["https"]
    },
    "queryStringParameters":{
        "city":"Seattle",
        "name":"John"
  },
  "multiValueQueryStringParameters":{
    "city":["Seattle"],
    "name":["John"]
  },
  "pathParameters":null,
  "stageVariables":null,
  "requestContext":{
    "resourceId":"3htbry",
    "resourcePath":"/helloworld",
    "httpMethod":"POST",
    "extendedRequestId":"a1b2c3d4e5f6g7h=",
    "requestTime":"20/Mar/2019:20:38:30 +0000",
    "path":"/test/helloworld",
    "accountId":"123456789012",
    "protocol":"HTTP/1.1",
    "stage":"test",
    "domainPrefix":"r275xc9bmd",
    "requestTimeEpoch":1553114310423,
    "requestId":"test-invoke-request",
    "identity":{
      "cognitoIdentityPoolId":null,
      "accountId":null,
      "cognitoIdentityId":null,
      "caller":null,
      "sourceIp":"test-invoke-source-ip",
      "accessKey":null,
      "cognitoAuthenticationType":null,
      "cognitoAuthenticationProvider":null,
      "userArn":null,
      "userAgent":"curl/0.0.0","user":null
    },
    "domainName":"r275xc9bmd.execute-api.us-east-1.amazonaws.com",
    "apiId":"r275xc9bmd"
  },
  "body": null,
  "isBase64Encoded":false
  }

If you are building unit tests, we include a request builder object. Check our examples here

@MounicaRamini
Copy link
Author

@sapessi Thanks. So, there might be something wrong in the request that am trying to send and test it out ? Just wanted an input

@MounicaRamini
Copy link
Author

@sapessi Thank You so much for patiently answering everything. It worked, I did make changes to Request Format.It brings up records now

thank you so much

@sapessi
Copy link
Collaborator

sapessi commented Oct 8, 2019

The event you were sending was correct in structure since the library was able to read it. However, there seem to be something broken in the value of the path property of the event - the log line without a space between the path and the protocol suggested there was a hidden character in the path that should not have been there, perhaps a \b.

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

No branches or pull requests

2 participants