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

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

Closed
rickbhardwaj opened this issue Jun 20, 2019 · 23 comments

Comments

@rickbhardwaj
Copy link

rickbhardwaj commented Jun 20, 2019

  • Framework version: 1.3.1
  • Implementation: Jersey

Scenario

I built a REST service using Jersey serverless container. Previously, sam local and the deployed lambda function had identical behavior.

Now, however, execution works against sam local (version 0.17.0,) albeit quite a bit slower than before, but does not execute when deployed to Lambda- it simply initializes the container, runs until timeout, and terminates the function. (perhaps related to the execution env upgrade?)

Logs attached:

Expected behavior

Invocation on sam local:

Ricks-MacBook-Pro-2:allende-war rick$ sam local start-api --template sam.yaml
2019-06-20 17:20:26 Mounting JerseySampleFunction at http://127.0.0.1:3000/{proxy+} [GET, DELETE, PUT, POST, HEAD, OPTIONS, PATCH]
2019-06-20 17:20:26 You can now browse to the above endpoints to invoke your functions. You do not need to restart/reload SAM CLI while working on your functions, changes will be reflected instantly/automatically. You only need to restart SAM CLI if you update your AWS SAM template
2019-06-20 17:20:26  * Running on http://127.0.0.1:3000/ (Press CTRL+C to quit)
2019-06-20 17:21:04 127.0.0.1 - - [20/Jun/2019 17:21:04] "GET / HTTP/1.1" 403 -
2019-06-20 17:21:06 Invoking com.mz.allende.config.StreamLambdaHandler::handleRequest (java8)
2019-06-20 17:21:06 Found credentials in shared credentials file: ~/.aws/credentials
2019-06-20 17:21:06 Decompressing /Users/rick/IdeaProjects/allende/allende-war/target/allende-war-1.5.0-SNAPSHOT-lambda-package.zip

Fetching lambci/lambda:java8 Docker container image......
2019-06-20 17:21:07 Mounting /private/var/folders/nd/7xg436m51nb5k7zc7pmc1bp80000gn/T/tmpcfo2_5mq as /var/task:ro,delegated inside runtime container
2019-06-20 17:21:11 Invoking com.mz.allende.config.StreamLambdaHandler::handleRequest (java8)
2019-06-20 17:21:11 Found credentials in shared credentials file: ~/.aws/credentials
2019-06-20 17:21:11 Decompressing /Users/rick/IdeaProjects/allende/allende-war/target/allende-war-1.5.0-SNAPSHOT-lambda-package.zip

Fetching lambci/lambda:java8 Docker container image......
2019-06-20 17:21:13 Mounting /private/var/folders/nd/7xg436m51nb5k7zc7pmc1bp80000gn/T/tmpnmlpmfzs as /var/task:ro,delegated inside runtime container
Jun 20, 2019 9:21:20 PM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime
WARNING: A provider com.mz.core.jersey.ws.server.resources.StatusApi$$EnhancerBySpringCGLIB$$a8400225 registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider com.mz.core.jersey.ws.server.resources.StatusApi$$EnhancerBySpringCGLIB$$a8400225 will be ignored.
Jun 20, 2019 9:21:20 PM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime
WARNING: A provider com.mz.core.jersey.ws.server.resources.DeepStatusApi$$EnhancerBySpringCGLIB$$a8f34e99 registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider com.mz.core.jersey.ws.server.resources.DeepStatusApi$$EnhancerBySpringCGLIB$$a8f34e99 will be ignored.
Jun 20, 2019 9:21:20 PM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime
WARNING: A provider com.sun.proxy.$Proxy59 registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider com.sun.proxy.$Proxy59 will be ignored.
Jun 20, 2019 9:21:20 PM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime
WARNING: A provider com.mz.core.jersey.ws.server.resources.InfoApi$$EnhancerBySpringCGLIB$$682fea29 registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider com.mz.core.jersey.ws.server.resources.InfoApi$$EnhancerBySpringCGLIB$$682fea29 will be ignored.
Jun 20, 2019 9:21:20 PM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime
WARNING: A provider com.sun.proxy.$Proxy58 registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider com.sun.proxy.$Proxy58 will be ignored.
START RequestId: f9381a24-8152-41ee-81ca-4956fbc99660 Version: $LATEST
END RequestId: f9381a24-8152-41ee-81ca-4956fbc99660
REPORT RequestId: f9381a24-8152-41ee-81ca-4956fbc99660	Duration: 515.28 ms	Billed Duration: 600 ms	Memory Size: 512 MB	Max Memory Used: 15 MB
21:21:10,007 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback-test.xml]
21:21:10,008 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback.groovy]
21:21:10,009 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Found resource [logback.xml] at [file:/var/task/logback.xml]
21:21:10,260 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
21:21:10,281 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [allende]
21:21:10,282 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
21:21:10,520 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
21:21:10,531 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [console]
21:21:10,656 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - This appender no longer admits a layout as a sub-component, set an encoder instead.
21:21:10,656 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
21:21:10,656 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
21:21:10,659 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [REQUEST] to TRACE
21:21:10,659 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [REQUEST] to false
21:21:10,660 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[REQUEST]
21:21:10,661 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [PERFORMANCE] to TRACE
21:21:10,661 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [PERFORMANCE] to false
21:21:10,661 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[PERFORMANCE]
21:21:10,661 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [COUNTER] to TRACE
21:21:10,661 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [COUNTER] to false
21:21:10,661 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[COUNTER]
21:21:10,666 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - Could not find Janino library on the class path. Skipping conditional processing.
21:21:10,666 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - See also http://logback.qos.ch/codes.html#ifJanino
21:21:10,668 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
21:21:10,669 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@3b088d51 - Registering current configuration as safe fallback point

21:21:21.603 [main] INFO  REQUEST - Server has received a request on thread main
> GET https://1234567890.execute-api.us-west-2.amazonaws.com:443/configurations

21:21:21.902 [main] INFO  REQUEST - Server responded with a response on thread main
< 200
< Content-Type: application/json
< Duration: 204
< SERVER_REQ_ID: 405a9c97-a33d-4ded-8f36-a09a9fbaa550
{"capacityConfiguration":{},"planningGranularity":0,"addressConsolidated":false,"deferrableRouteSupported":false,"territorial":false,"dynamicRoutingHub":false}

Actual behavior

Invocation on deployed Lambda function:

{"message": "Internal server error"}

Full log output

From CloudWatch logs of deployed Lambda function:

END RequestId: a79c7193-6ea5-40a1-bbd4-ce7e9d87412b
REPORT RequestId: a79c7193-6ea5-40a1-bbd4-ce7e9d87412b	Duration: 15014.69 ms	Billed Duration: 15000 ms Memory Size: 512 MB	Max Memory Used: 138 MB	
2019-06-20T21:25:37.191Z a79c7193-6ea5-40a1-bbd4-ce7e9d87412b Task timed out after 15.01 seconds

21:25:37,871 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback-test.xml]
21:25:37,871 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback.groovy]
21:25:37,872 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Found resource [logback.xml] at [file:/var/task/logback.xml]
21:25:38,171 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
21:25:38,209 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [allende]
21:25:38,209 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
21:25:38,309 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
21:25:38,316 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [console]
21:25:38,435 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - This appender no longer admits a layout as a sub-component, set an encoder instead.
21:25:38,435 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
21:25:38,435 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
21:25:38,436 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [REQUEST] to TRACE
21:25:38,436 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [REQUEST] to false
21:25:38,437 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[REQUEST]
21:25:38,437 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [PERFORMANCE] to TRACE
21:25:38,437 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [PERFORMANCE] to false
21:25:38,437 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[PERFORMANCE]
21:25:38,437 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [COUNTER] to TRACE
21:25:38,437 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [COUNTER] to false
21:25:38,437 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[COUNTER]
21:25:38,438 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - Could not find Janino library on the class path. Skipping conditional processing.
21:25:38,438 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - See also http://logback.qos.ch/codes.html#ifJanino
21:25:38,440 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
21:25:38,441 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4f063c0a - Registering current configuration as safe fallback point

Steps to reproduce

My StreamLambdaHandler class:

public class StreamLambdaHandler implements RequestStreamHandler {

    private static final JerseyLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;

    static {
        try {
            handler = JerseyLambdaContainerHandler.getAwsProxyHandler(getJerseyServerApplication());
        } catch (Exception e) {
            // if we fail here. We re-throw the exception to force another cold start
            e.printStackTrace();
            throw new RuntimeException("Could not initialize jersey container", e);
        }
    }

    @Override
    public void handleRequest(InputStream inputStream, OutputStream outputStream, Context context) throws IOException {
        try {
            handler.proxyStream(inputStream, outputStream, context);
        } catch (Exception e) {
            // if we fail here. We re-throw the exception to force another cold start
            e.printStackTrace();
            throw new RuntimeException("Could not handle request", e);
        }
    }

    @SneakyThrows
    private static SimpleResourceConfig getJerseyServerApplication() {

        AnnotationConfigApplicationContext context = new AnnotationConfigApplicationContext();
        context.register(ServiceConfig.class);
        context.refresh();

        return context.getBean(SimpleResourceConfig.class);
    }
}
@sapessi
Copy link
Collaborator

sapessi commented Jun 20, 2019

Thanks @rickbhardwaj, I'll try to replicate with your code and let you know. To be clear, you don't see any exception, the code just hangs until the Lambda function times out?

@sapessi
Copy link
Collaborator

sapessi commented Jun 20, 2019

The Lambda logs in the issue only cover 2seconds of an execution. Can you attach a more complete log? Which version of Jersey are you using?

@rickbhardwaj
Copy link
Author

Hi @sapessi , I think this is the complete log. But it's the same takeaway- some startup logging, run until time out, and ends execution.

16:51:48,653 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback-test.xml]
16:51:48,654 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback.groovy]
16:51:48,654 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Found resource [logback.xml] at [file:/var/task/logback.xml]
16:51:49,026 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
16:51:49,033 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [allende]
16:51:49,033 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
16:51:49,172 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:51:49,189 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [console]
16:51:49,303 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - This appender no longer admits a layout as a sub-component, set an encoder instead.
16:51:49,303 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
16:51:49,303 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
16:51:49,305 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [REQUEST] to TRACE
16:51:49,305 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [REQUEST] to false
16:51:49,305 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[REQUEST]
16:51:49,305 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [PERFORMANCE] to TRACE
16:51:49,305 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [PERFORMANCE] to false
16:51:49,306 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[PERFORMANCE]
16:51:49,306 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [COUNTER] to TRACE
16:51:49,306 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [COUNTER] to false
16:51:49,306 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[COUNTER]
16:51:49,307 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - Could not find Janino library on the class path. Skipping conditional processing.
16:51:49,307 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - See also http://logback.qos.ch/codes.html#ifJanino
16:51:49,309 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:51:49,309 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4f063c0a - Registering current configuration as safe fallback point

START RequestId: 3b5ca17e-e59a-4107-95e0-e8723cd4d1b4 Version: $LATEST
16:51:59,609 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback-test.xml]
16:51:59,610 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback.groovy]
16:51:59,610 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Found resource [logback.xml] at [file:/var/task/logback.xml]
16:52:00,475 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
16:52:00,509 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [allende]
16:52:00,509 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
16:52:00,791 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:52:00,810 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [console]
16:52:01,152 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - This appender no longer admits a layout as a sub-component, set an encoder instead.
16:52:01,152 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
16:52:01,152 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
16:52:01,170 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [REQUEST] to TRACE
16:52:01,170 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [REQUEST] to false
16:52:01,170 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[REQUEST]
16:52:01,171 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [PERFORMANCE] to TRACE
16:52:01,171 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [PERFORMANCE] to false
16:52:01,171 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[PERFORMANCE]
16:52:01,171 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [COUNTER] to TRACE
16:52:01,171 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [COUNTER] to false
16:52:01,171 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[COUNTER]
16:52:01,172 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - Could not find Janino library on the class path. Skipping conditional processing.
16:52:01,172 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - See also http://logback.qos.ch/codes.html#ifJanino
16:52:01,174 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:52:01,174 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1c3a4799 - Registering current configuration as safe fallback point

END RequestId: 3b5ca17e-e59a-4107-95e0-e8723cd4d1b4
REPORT RequestId: 3b5ca17e-e59a-4107-95e0-e8723cd4d1b4	Duration: 15015.24 ms	Billed Duration: 15000 ms Memory Size: 512 MB	Max Memory Used: 128 MB	
2019-06-21T16:52:13.485Z 3b5ca17e-e59a-4107-95e0-e8723cd4d1b4 Task timed out after 15.02 seconds

16:52:14,155 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback-test.xml]
16:52:14,156 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Could NOT find resource [logback.groovy]
16:52:14,156 |-INFO in ch.qos.logback.classic.LoggerContext[allende] - Found resource [logback.xml] at [file:/var/task/logback.xml]
16:52:14,481 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
16:52:14,491 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [allende]
16:52:14,491 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
16:52:14,591 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:52:14,597 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [console]
16:52:14,733 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - This appender no longer admits a layout as a sub-component, set an encoder instead.
16:52:14,733 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
16:52:14,733 |-WARN in ch.qos.logback.core.ConsoleAppender[console] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
16:52:14,734 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [REQUEST] to TRACE
16:52:14,734 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [REQUEST] to false
16:52:14,734 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[REQUEST]
16:52:14,735 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [PERFORMANCE] to TRACE
16:52:14,735 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [PERFORMANCE] to false
16:52:14,735 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[PERFORMANCE]
16:52:14,735 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [COUNTER] to TRACE
16:52:14,735 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [COUNTER] to false
16:52:14,735 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [console] to Logger[COUNTER]
16:52:14,736 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - Could not find Janino library on the class path. Skipping conditional processing.
16:52:14,736 |-ERROR in ch.qos.logback.core.joran.conditional.IfAction - See also http://logback.qos.ch/codes.html#ifJanino
16:52:14,738 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:52:14,738 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4f063c0a - Registering current configuration as safe fallback point

@rickbhardwaj
Copy link
Author

@sapessi I'm using jersey version 2.26

@sapessi
Copy link
Collaborator

sapessi commented Jun 21, 2019

Looks like you are using Spring. Why use it inside Jersey and not go straight for the Spring implementation of this framework?

@rickbhardwaj
Copy link
Author

rickbhardwaj commented Jun 21, 2019

Some extra context: here is my sam.yaml

AWSTemplateFormatVersion: '2010-09-09'
Transform: AWS::Serverless-2016-10-31
Description: AWS Serverless Jersey API - my.service::allende

Resources:
  JerseySampleFunction:
    Type: AWS::Serverless::Function
    Properties:
      Handler: com.mz.allende.config.StreamLambdaHandler::handleRequest
      Runtime: java8
      CodeUri: target/allende-war-1.5.0-SNAPSHOT-lambda-package.zip
      MemorySize: 512
      Policies: AWSLambdaBasicExecutionRole
      Timeout: 15
      Events:
        GetResource:
          Type: Api
          Properties:
            Path: /{proxy+}
            Method: any


Outputs:
  AllendeApi:
    Description: URL for application
    Value: !Sub 'https://${ServerlessRestApi}.execute-api.${AWS::Region}.amazonaws.com/'
    Export:
      Name: AllendeApi

and I am invoking the API Gateway with https://******.execute-api.us-west-2.amazonaws.com/Stage/configurations

@rickbhardwaj
Copy link
Author

rickbhardwaj commented Jun 21, 2019

@sapessi I'm using Spring mostly just for dependency injection and caching. I'm using jersey for the actual REST/JAX-RS implementation.

@sapessi
Copy link
Collaborator

sapessi commented Jun 21, 2019

I've never tried the two together. I can take a look into it. Out of curiosity, why Spring instead of the built-in hk2? My recommendation for Lambda normally is Dagger2 for performance reasons, although I know it doesn't integrate nicely with Jersey. Spring is really slow to initialize inside Lambda.

@rickbhardwaj
Copy link
Author

rickbhardwaj commented Jun 21, 2019

Yeah I saw your comments here. Mostly I'm trying to write a library for my team to easily port our existing services to Lambda, and this is our setup. Asking them to rewrite their applications to switch from spring to dagger will mean nobody will use my library haha.

@sapessi
Copy link
Collaborator

sapessi commented Jun 21, 2019

Fair, is there any code you can share with me so that I can try and replicate with your code?

@rickbhardwaj
Copy link
Author

Sure, I'm using this on a toy service built with our setup, I can share most of it. You won't be able to build it because it depends on some libraries in our maven repo, but I think you can see how we're approaching it.

Just to confirm, have other users reported any issues with the jersey library since the execution environment upgrade?

@sapessi
Copy link
Collaborator

sapessi commented Jun 21, 2019

No, this is the first time I see it. some code is better than nothing.

@rickbhardwaj
Copy link
Author

Sorry for the delay @sapessi. After seeing this thread, I realized I hadn't tried turning on the lazyInit flag on my Spring @ComponentScans. I deployed the function and it started working very quickly. I thought I had solved it, but then I made another minor change and deployed again- back to not working. I'll share the code in a second.

@sapessi
Copy link
Collaborator

sapessi commented Jun 21, 2019

Sounds good. My guess is that you are running into the 10 seconds limit for the init time. Lambda allows a max of 10 seconds for your handler class to instantiate, if you take longer than that, it will assume the sandbox is dead and discard it. It is possible that behind the scenes spring is taking a long time to initialize without logging anything useful for you.

I had planned to address this in 1.4 by creating an async initializer that runs in a separate thread for a max of 10 seconds, then releases the latch for the constructor to complete. Another latch then holds the handler execution until the initialization is actually complete.

@rickbhardwaj
Copy link
Author

That sounds very likely, and would explain why it runs on sam local and suddenly started working after a lazyInit flag was enabled. The first execution took 500 ms, but the subsequent ones took ~5ms before my next deployment.

@rickbhardwaj
Copy link
Author

Here, this is basically what I'm building.

Important classes are: StreamLambdaHandler, RoutingConfigurationApi, RoutingConfigurationActivity

allende-public_view.zip

@rickbhardwaj
Copy link
Author

I'm going to try to get rid of the component scan call.

@rickbhardwaj
Copy link
Author

I tried using the spring-context-indexer and the deployed lambda function began working. However, I'm not sure if this is just luck on Spring init and will revert back at some point.

@sapessi
Copy link
Collaborator

sapessi commented Jun 21, 2019

It is, you'll be safer by slightly increasing the memory allocated to the function - however, still unpredictable. I would say move the init code to the handler method (lazy load) so that Lambda will continue no matter what (although your first invocation will be even slower). I will keep this issue open for the implementation of the async init in version 1.4 of the framework.

@sapessi sapessi added this to the Release 1.4 milestone Jun 21, 2019
@rickbhardwaj
Copy link
Author

The first successful invocation took 880 ms. If we're right about this being part of the ten second limit on init, that is close. I'll try increasing the memory and see if I can move the init to the handler (not completely sure, there might be circular dependency since I need spring initialized in the handler.)

@sapessi
Copy link
Collaborator

sapessi commented Sep 26, 2019

Hi @rickbhardwaj, better late than never we have a fix for this about to go out in the next release. See my comment in this other issue.

@sapessi
Copy link
Collaborator

sapessi commented Sep 30, 2019

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

@sapessi sapessi closed this as completed Sep 30, 2019
@sandun-sanmark
Copy link

sandun-sanmark commented Jul 1, 2021

Your response should be like
response = {
"headers": {
"Content-Type": "application/json"
},
'statusCode': 200,
'body': JSON.stringify(payload)
};

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