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

Amazon Lambda HTTP resolve native test issues from #7362 #9697

Closed
wants to merge 1 commit into from

Conversation

oztimpower
Copy link
Contributor

Issue #7362 identified a couple of problems, first that the undertow host localhost:5387 was not being set for native tests, and second some ugly shutdown exceptions.

Addressed the shutdown issues for the Amazon Lambda HTTP in AbstractLambdaPollLoop where the requestId was being read on a closed socket (thread no longer running).

Also identified an issue in the maven-archetype where the Funqy tests were returning application/json. \cc @patriot1burke. Added the AwsProxy versions of the unit tests, which is used in the quarkus integration tests. The AwsProxy tests also work on native (RestAssured does not), yet left the RestAssured version in the maven-archetype as it works with the JVM.

Shutdown exceptions per #7362 Native Tests pre the change:

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running io.quarkus.qe.NativeMyResourceIT
Executing [/private/var/tmp/barFoo/target/barFoo-1.0.0-SNAPSHOT-runner, -Dquarkus.http.port=8081, -Dquarkus.http.ssl-port=8444, -Dtest.url=http://localhost:8081, -Dquarkus.log.file.path=target/quarkus.log, -Dquarkus-internal.aws-lambda.test-api=localhost:5387]
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2020-05-31 15:55:42,424 INFO  [io.quarkus] (main) barFoo 1.0.0-SNAPSHOT native (powered by Quarkus 999-SNAPSHOT) started in 0.018s. 
2020-05-31 15:55:42,424 INFO  [io.quarkus] (main) Profile prod activated. 
2020-05-31 15:55:42,424 INFO  [io.quarkus] (main) Installed features: [amazon-lambda, cdi, resteasy]
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.513 s - in io.quarkus.qe.NativeMyResourceIT
2020-05-31 15:55:43,629 ERROR [io.qua.ama.lam.run.AbstractLambdaPollLoop] (Lambda Thread) Failed to run lambda: java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:186)
	at java.net.SocketInputStream.read(SocketInputStream.java:140)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:292)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:351)
	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:754)
	at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:689)
	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:863)
	at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:689)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1610)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1515)
	at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:3094)
	at io.quarkus.amazon.lambda.runtime.AbstractLambdaPollLoop$1.run(AbstractLambdaPollLoop.java:50)
	at java.lang.Thread.run(Thread.java:834)
	at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:517)
	at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)

May 31, 2020 3:55:43 PM io.netty.bootstrap.ServerBootstrap$ServerBootstrapAcceptor forceClose
WARN: Failed to register an accepted channel: [id: 0x24df1aca, L:0.0.0.0/0.0.0.0:5387]
java.lang.IllegalStateException
	at io.vertx.core.net.impl.VertxEventLoopGroup.next(VertxEventLoopGroup.java:37)
	at io.vertx.core.net.impl.VertxEventLoopGroup.register(VertxEventLoopGroup.java:53)
	at io.netty.bootstrap.ServerBootstrap$ServerBootstrapAcceptor.channelRead(ServerBootstrap.java:218)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:93)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:484)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:834)

[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0
[INFO] 

Post the changes to AbstractLambdaPollLoop Native Tests on #7362:

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running io.quarkus.qe.NativeMyResourceIT
Executing [/private/var/tmp/barFoo/target/barFoo-1.0.0-SNAPSHOT-runner, -Dquarkus.http.port=8081, -Dquarkus.http.ssl-port=8444, -Dtest.url=http://localhost:8081, -Dquarkus.log.file.path=target/quarkus.log, -Dquarkus-internal.aws-lambda.test-api=localhost:5387]
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2020-05-31 16:04:16,350 INFO  [io.quarkus] (main) barFoo 1.0.0-SNAPSHOT native (powered by Quarkus 999-SNAPSHOT) started in 0.018s. 
2020-05-31 16:04:16,351 INFO  [io.quarkus] (main) Profile prod activated. 
2020-05-31 16:04:16,351 INFO  [io.quarkus] (main) Installed features: [amazon-lambda, cdi, resteasy]
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.391 s - in io.quarkus.qe.NativeMyResourceIT
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0
[INFO] 

Archetype tested by:

mvn archetype:generate \
       -DarchetypeGroupId=io.quarkus \
       -DarchetypeArtifactId=quarkus-amazon-lambda-http-archetype \
       -DarchetypeVersion=999-SNAPSHOT

mvn verify # all tests now work - Funqy was failing with content type = application\json

@patriot1burke
Copy link
Contributor

@oztimpower Please see: #9717

This has resolved/removed exception stack trace issues when running with test harness.

new FunctionError(e.getClass().getName(), e.getMessage()));
continue;
} catch (IOException ioException) {
break;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Won't eating the exception hide other errors?

Copy link
Contributor Author

@oztimpower oztimpower Jun 3, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The error has already been logged to the console (and hence CloudWatch Logs), before there is an additional attempt to log it to the Lambda service. If the latter fails, there is a more fundamental problem and you should logically exit, indeed that is what the double try-catch was doing at any rate, practically all that was happening was the same exception being shown twice. Outcome was the same.

It was evident in the test framework, that it wasn't adding a lot of value double counting the fact that the thread had closed which is what was triggering the errors. Either way that code needs a bit of re-think in terms of how it is reporting errors to the console and the lambda service. Lambda will log all console stdout and stderr to CloudWatch Logs.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My latest PR at least got rid of the stack traces when running with the test harness. Just merged.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For Native Tests? That is where the exceptions were being thrown. I've tested #7362 again post the PR and it is still failing with the same stack trace.

The AbstractLambdaPollLoop is invoked only when using native-image or when the property quarkus.lambda.enable-polling-jvm-mode=true by virtue of the AmazonLambdaProcessor build steps. That is what this PR is addressing.

public void testGetTextFunqy() throws Exception {
testGetText("/funqyHello","application/json", "\"hello funqy\"");
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@patriot1burke

FYI, there is an issue with the Funqy tests, it is using content type application/json and generates the below errors when run from the maven archetype (this needs to be fixed). I modified it here.

mvn archetype:generate \
        -DarchetypeGroupId=io.quarkus \
        -DarchetypeArtifactId=quarkus-amazon-lambda-http-archetype \
        -DarchetypeVersion=999-SNAPSHOT


[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.tjpower.GreetingTest
2020-06-04 10:35:43,346 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT on JVM started in 1.833s. Listening on: http://0.0.0.0:8081
2020-06-04 10:35:43,347 INFO  [io.quarkus] (main) Profile test activated. 
2020-06-04 10:35:43,348 INFO  [io.quarkus] (main) Installed features: [amazon-lambda, cdi, funqy-http, mutiny, resteasy, servlet, vertx, vertx-web]
[ERROR] Tests run: 4, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 4.508 s <<< FAILURE! - in org.tjpower.GreetingTest
[ERROR] testFunqy  Time elapsed: 1.058 s  <<< FAILURE!
java.lang.AssertionError: 
1 expectation failed.
Expected content-type "text/plain" doesn't match actual content-type "application/json".

	at org.tjpower.GreetingTest.testFunqy(GreetingTest.java:36)

2020-06-04 10:35:44,659 INFO  [io.quarkus] (main) Quarkus stopped in 0.102s
[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   GreetingTest.testFunqy:36 1 expectation failed.
Expected content-type "text/plain" doesn't match actual content-type "application/json".

[INFO] 
[ERROR] Tests run: 4, Failures: 1, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  17.379 s
[INFO] Finished at: 2020-06-04T10:35:45Z
[INFO] ————————————————————————————————————

@oztimpower
Copy link
Contributor Author

I will split this up, seperate the Maven Archetype issue.

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

Successfully merging this pull request may close these issues.

3 participants