Potential regression between java8 and java11 (invocation recompiles the .jar classes)

[kwojcik-blockether]

Description:

When using java11 version of rapid image it seems that runtime tries to recompile files in .jar file. This issue did not happen on java8 runtime. Before introducing version 1.21 of sam-cli this error happened only when invoking function directly on java11. Now happens even when using sam local start-api.

Since I got the same issue not only when invoking function directly I doubt it's a problem of a language (Clojure). I suspect the problem here is the runtime. Compiling&Running the same code with GraalVM Java11 (specs are included) does not trigger the error.

Steps to reproduce:

Reproduction here: kwojcik-blockether/holy-lambda#26

Expected result:

I would expect that the lambda function would run seamlessly the same as it was running on java8.

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

1. OS: Windows, Mac, Linux
2. sam --version: 1.21, 1.19
3. AWS region: does not matter

EDIT: Please use the following commit: kwojcik-blockether/holy-lambda@848e40a

[sriram-mv]

Some background questions, you mentioned that this was working previous to 1.21.

SAM CLI emulation images for java11 are published here: https://hub.docker.com/r/amazon/aws-sam-cli-emulation-image-java11/tags?page=1&ordering=last_updated

I have not dived too deeply yet, but the only thing that could have changed is the underlying image, as the logic for the invoking function is just passed to the container, along with lambda runtime interface https://github.com/aws/aws-lambda-runtime-interface-emulator.

Is there a particular image that used to work from that list? you can pull down an image and re-tag it as the underlying image and then try to do a local invoke while specifying --skip-pull-image

[kwojcik-blockether]

@sriram-mv

Some background questions, you mentioned that this was working previous to 1.21.

One of the users reported this issue kwojcik-blockether/holy-lambda#26 on Jan 3. At that time local start-api was working fine on 1.19, but invoke was broken. Now both are broken and the result is a reported error. Java 8 works like a charm! I believe that month maybe few months before Jan 3 there was no such issue. Hope that helps at least a little bit. The interesting part for you is probably that one: At that time local start-api was working fine on 1.19, but invoke was broken.

Regarding testing I need specific info how should I run it through SAM.

Here is what I tried:

docker pull amazon/aws-sam-cli-emulation-image-java11:20210113
docker tag amazon/aws-sam-cli-emulation-image-java11:20210113 amazon/aws-sam-cli-emulation-image-java11:rapid-1.22.0
sam local start-api --skip-image

error

exec: "/var/rapid/aws-lambda-rie": stat /var/rapid/aws-lambda-rie: no such file or directory: unknown")

should I somehow merge rie and emulation images?

[sriram-mv]

@FieryCod SAM CLI will do the merging for you.

After pulling amazon/aws-sam-cli-emulation-image-java11:20210113

remove the image which has rapid-1.22.0 tag.

docker rmi -f amazon/aws-sam-cli-emulation-image-java11:rapid-1.22.0

Now retag.

docker tag amazon/aws-sam-cli-emulation-image-java11:20210113 amazon/aws-sam-cli-emulation-image-java11:latest

finally

sam local start-api --skip-pull-image

[kwojcik-blockether]

@sriram-mv Thank you very much. Just checked amazon/aws-sam-cli-emulation-image-java11:20201120 and as stated local start-api works just fine. Suprisingly invoke does not. This the oldest release I can find, therefore I was partially wrong invoke was not working on java11 with Clojure even few months back.

[kwojcik-blockether]

@sriram-mv Any conclusions here?

[kwojcik-blockether]

@SimonCMoore @sriram-mv @mingkun2020

This issue is really important to me. I have produced a minimized version of the above. The reproduction is now very minimal and follows Official AWS Lambda Clojure guidelines. The deployment works flawlessly. There is no error on real AWS Lambda service, meanwhile using sam local invoke and sam local start-api produce the following error on Java11:

❯ sam local invoke ClojureOnJava11  
Invoking example.lambda (java11)
Decompressing /home/fierycod/java-11-8-aws-sam-2787/java11.jar
Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-java11:rapid-1.26.0.

Mounting /tmp/tmp98okg4qd as /var/task:ro,delegated inside runtime container
START RequestId: 77b8622d-3e01-4173-bb05-ed76e2c21e73 Version: $LATEST
Error loading class example.lambda: java.lang.ExceptionInInitializerError
java.lang.ExceptionInInitializerError
        at java.base/java.lang.Class.forName0(Native Method)
        at java.base/java.lang.Class.forName(Unknown Source)
        at clojure.lang.RT.classForName(RT.java:2212)
        at clojure.lang.RT.classForName(RT.java:2221)
        at clojure.lang.RT.loadClassForName(RT.java:2240)
        at clojure.lang.RT.load(RT.java:449)
        at clojure.lang.RT.load(RT.java:424)
        at clojure.core$load$fn__6856.invoke(core.clj:6115)
        at clojure.core$load.invokeStatic(core.clj:6114)
        at clojure.core$load.doInvoke(core.clj:6098)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.core$load_one.invokeStatic(core.clj:5897)
        at clojure.core$load_one.invoke(core.clj:5892)
        at clojure.core$load_lib$fn__6796.invoke(core.clj:5937)
        at clojure.core$load_lib.invokeStatic(core.clj:5936)
        at clojure.core$load_lib.doInvoke(core.clj:5917)
        at clojure.lang.RestFn.applyTo(RestFn.java:142)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$load_libs.invokeStatic(core.clj:5974)
        at clojure.core$load_libs.doInvoke(core.clj:5958)
        at clojure.lang.RestFn.applyTo(RestFn.java:137)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$require.invokeStatic(core.clj:5996)
        at clojure.main$loading__6737__auto____8998.invoke(main.clj:11)
        at clojure.main__init.load(Unknown Source)
        at clojure.main__init.<clinit>(Unknown Source)
        at java.base/java.lang.Class.forName0(Native Method)
        at java.base/java.lang.Class.forName(Unknown Source)
        at clojure.lang.RT.classForName(RT.java:2212)
        at clojure.lang.RT.classForName(RT.java:2221)
        at clojure.lang.RT.loadClassForName(RT.java:2240)
        at clojure.lang.RT.load(RT.java:449)
        at clojure.lang.RT.load(RT.java:424)
        at clojure.core$load$fn__6856.invoke(core.clj:6115)
        at clojure.core$load.invokeStatic(core.clj:6114)
        at clojure.core$load.doInvoke(core.clj:6098)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.core$load_one.invokeStatic(core.clj:5897)
        at clojure.core$load_one.invoke(core.clj:5892)
        at clojure.core$load_lib$fn__6796.invoke(core.clj:5937)
        at clojure.core$load_lib.invokeStatic(core.clj:5936)
        at clojure.core$load_lib.doInvoke(core.clj:5917)
        at clojure.lang.RestFn.applyTo(RestFn.java:142)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$load_libs.invokeStatic(core.clj:5974)
        at clojure.core$load_libs.doInvoke(core.clj:5958)
        at clojure.lang.RestFn.applyTo(RestFn.java:137)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$require.invokeStatic(core.clj:5996)
        at clojure.core.server$loading__6737__auto____8865.invoke(server.clj:9)
        at clojure.core.server__init.load(Unknown Source)
        at clojure.core.server__init.<clinit>(Unknown Source)
        at java.base/java.lang.Class.forName0(Native Method)
        at java.base/java.lang.Class.forName(Unknown Source)
        at clojure.lang.RT.classForName(RT.java:2212)
        at clojure.lang.RT.classForName(RT.java:2221)
        at clojure.lang.RT.loadClassForName(RT.java:2240)
        at clojure.lang.RT.load(RT.java:449)
        at clojure.lang.RT.load(RT.java:424)
        at clojure.core$load$fn__6856.invoke(core.clj:6115)
        at clojure.core$load.invokeStatic(core.clj:6114)
        at clojure.core$load.doInvoke(core.clj:6098)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.core$load_one.invokeStatic(core.clj:5897)
        at clojure.core$load_one.invoke(core.clj:5892)
        at clojure.core$load_lib$fn__6796.invoke(core.clj:5937)
        at clojure.core$load_lib.invokeStatic(core.clj:5936)
        at clojure.core$load_lib.doInvoke(core.clj:5917)
        at clojure.lang.RestFn.applyTo(RestFn.java:142)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$load_libs.invokeStatic(core.clj:5974)
        at clojure.core$load_libs.doInvoke(core.clj:5958)
        at clojure.lang.RestFn.applyTo(RestFn.java:137)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$require.invokeStatic(core.clj:5996)
        at clojure.core$require.doInvoke(core.clj:5996)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.lang.Var.invoke(Var.java:384)
        at clojure.lang.RT.doInit(RT.java:491)
        at clojure.lang.RT.init(RT.java:467)
        at clojure.lang.Util.loadWithClass(Util.java:248)
        at example.lambda.<clinit>(Unknown Source)
        at java.base/java.lang.Class.forName0(Native Method)
        at java.base/java.lang.Class.forName(Unknown Source)
Caused by: Syntax error macroexpanding clojure.core/ns at (clojure/walk.clj:21:1).
Syntax error compiling at (clojure/core/specs/alpha.clj:1:1).
        at clojure.lang.Compiler.checkSpecs(Compiler.java:6976)
        at clojure.lang.Compiler.macroexpand1(Compiler.java:6992)
        at clojure.lang.Compiler.macroexpand(Compiler.java:7079)
        at clojure.lang.Compiler.eval(Compiler.java:7165)
        at clojure.lang.Compiler.load(Compiler.java:7640)
        at clojure.lang.RT.loadResourceScript(RT.java:381)
        at clojure.lang.RT.loadResourceScript(RT.java:372)
        at clojure.lang.RT.load(RT.java:459)
        at clojure.lang.RT.load(RT.java:424)
        at clojure.core$load$fn__6856.invoke(core.clj:6115)
        at clojure.core$load.invokeStatic(core.clj:6114)
        at clojure.core$load.doInvoke(core.clj:6098)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.core$load_one.invokeStatic(core.clj:5897)
        at clojure.core$load_one.invoke(core.clj:5892)
        at clojure.core$load_lib$fn__6796.invoke(core.clj:5937)
        at clojure.core$load_lib.invokeStatic(core.clj:5936)
        at clojure.core$load_lib.doInvoke(core.clj:5917)
        at clojure.lang.RestFn.applyTo(RestFn.java:142)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$load_libs.invokeStatic(core.clj:5974)
        at clojure.core$load_libs.doInvoke(core.clj:5958)
        at clojure.lang.RestFn.applyTo(RestFn.java:137)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$require.invokeStatic(core.clj:5996)
        at clojure.core$require.doInvoke(core.clj:5996)
        at clojure.lang.RestFn.invoke(RestFn.java:436)
        at clojure.spec.alpha$loading__6721__auto____1654.invoke(alpha.clj:9)
        at clojure.spec.alpha__init.load(Unknown Source)
        at clojure.spec.alpha__init.<clinit>(Unknown Source)
        ... 84 more
Caused by: Syntax error compiling at (clojure/core/specs/alpha.clj:1:1).
        at clojure.core$throw_if.invokeStatic(core.clj:5856)
        at clojure.core$check_cyclic_dependency.invokeStatic(core.clj:5988)
        at clojure.core$load.invokeStatic(core.clj:6109)
        at clojure.core$load.doInvoke(core.clj:6098)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.core$load_one.invokeStatic(core.clj:5897)
        at clojure.core$load_one.invoke(core.clj:5892)
        at clojure.core$load_lib$fn__6796.invoke(core.clj:5937)
        at clojure.core$load_lib.invokeStatic(core.clj:5936)
        at clojure.core$load_lib.doInvoke(core.clj:5917)
        at clojure.lang.RestFn.applyTo(RestFn.java:142)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$load_libs.invokeStatic(core.clj:5974)
        at clojure.core$load_libs.doInvoke(core.clj:5958)
        at clojure.lang.RestFn.applyTo(RestFn.java:137)
        at clojure.core$apply.invokeStatic(core.clj:669)
        at clojure.core$require.invokeStatic(core.clj:5996)
        at clojure.core$require.doInvoke(core.clj:5996)
        at clojure.lang.RestFn.invoke(RestFn.java:408)
        at clojure.core.specs.alpha$eval1397$loading__6737__auto____1398.invoke(alpha.clj:1)
        at clojure.core.specs.alpha$eval1397.invokeStatic(alpha.clj:1)
        at clojure.core.specs.alpha$eval1397.invoke(alpha.clj:1)
        at clojure.lang.Compiler.eval(Compiler.java:7181)
        at clojure.lang.Compiler.eval(Compiler.java:7170)
        at clojure.lang.Compiler.load(Compiler.java:7640)
        at clojure.lang.RT.loadResourceScript(RT.java:381)
        at clojure.lang.RT.loadResourceScript(RT.java:372)
        at clojure.lang.RT.load(RT.java:459)
        at clojure.lang.RT.load(RT.java:424)
        at clojure.lang.Compiler.ensureMacroCheck(Compiler.java:6962)
        at clojure.lang.Compiler.checkSpecs(Compiler.java:6974)
        ... 113 more
Caused by: java.lang.Exception: Cyclic load dependency: [ /clojure/spec/alpha ]->/clojure/walk->[ /clojure/spec/alpha ]->/clojure/main->/clojure/core/server
        ... 139 more

time="2021-07-21T06:18:03.86" level=panic msg="ReplyStream not available"
2021/07/21 06:18:03 http: panic serving 127.0.0.1:50280: &{0xc000146000 map[] 2021-07-21 06:18:03.86024971 +0000 UTC m=+2.883306523 panic <nil> ReplyStream not available <nil> <nil> }
goroutine 13 [running]:
net/http.(*conn).serve.func1(0xc000114d20)
        /usr/local/go/src/net/http/server.go:1800 +0x139
panic(0x866640, 0xc0002320e0)
        /usr/local/go/src/runtime/panic.go:975 +0x3e3
github.com/sirupsen/logrus.Entry.log(0xc000146000, 0xc0002340f0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /go/pkg/mod/github.com/sirupsen/logrus@v1.6.0/entry.go:259 +0x335
github.com/sirupsen/logrus.(*Entry).Log(0xc000232070, 0xc000000000, 0xc00020d588, 0x1, 0x1)
        /go/pkg/mod/github.com/sirupsen/logrus@v1.6.0/entry.go:287 +0xeb
github.com/sirupsen/logrus.(*Logger).Log(0xc000146000, 0xc000000000, 0xc00020d588, 0x1, 0x1)
        /go/pkg/mod/github.com/sirupsen/logrus@v1.6.0/logger.go:193 +0x7d
github.com/sirupsen/logrus.(*Logger).Panic(...)
        /go/pkg/mod/github.com/sirupsen/logrus@v1.6.0/logger.go:234
github.com/sirupsen/logrus.Panic(...)
        /go/pkg/mod/github.com/sirupsen/logrus@v1.6.0/exported.go:129
go.amzn.com/lambda/rapi/rendering.RenderInteropError(0x9097c0, 0xc000244000, 0xc00024c100, 0x902b60, 0xc0002400a0)
        /LambdaRuntimeLocal/lambda/rapi/rendering/rendering.go:292 +0x9a
go.amzn.com/lambda/rapi/handler.(*initErrorHandler).ServeHTTP(0xc00009c0a0, 0x9097c0, 0xc000244000, 0xc00024c100)
        /LambdaRuntimeLocal/lambda/rapi/handler/initerror.go:52 +0x519
net/http.HandlerFunc.ServeHTTP(0xc000094380, 0x9097c0, 0xc000244000, 0xc00024c100)
        /usr/local/go/src/net/http/server.go:2041 +0x44
github.com/go-chi/chi.(*Mux).routeHTTP(0xc0000a60c0, 0x9097c0, 0xc000244000, 0xc00024c100)
        /go/pkg/mod/github.com/go-chi/chi@v4.1.2+incompatible/mux.go:431 +0x278
net/http.HandlerFunc.ServeHTTP(0xc00009c030, 0x9097c0, 0xc000244000, 0xc00024c100)
        /usr/local/go/src/net/http/server.go:2041 +0x44
go.amzn.com/lambda/rapi/middleware.RuntimeReleaseMiddleware.func1.1(0x9097c0, 0xc000244000, 0xc00024c100)
        /LambdaRuntimeLocal/lambda/rapi/middleware/middleware.go:100 +0xea
net/http.HandlerFunc.ServeHTTP(0xc000094180, 0x9097c0, 0xc000244000, 0xc00024c100)
        /usr/local/go/src/net/http/server.go:2041 +0x44
go.amzn.com/lambda/rapi/middleware.AccessLogMiddleware.func1.1(0x9097c0, 0xc000244000, 0xc00024c100)
        /LambdaRuntimeLocal/lambda/rapi/middleware/middleware.go:77 +0x170
net/http.HandlerFunc.ServeHTTP(0xc0000941a0, 0x9097c0, 0xc000244000, 0xc00024c100)
        /usr/local/go/src/net/http/server.go:2041 +0x44
go.amzn.com/lambda/rapi/middleware.AppCtxMiddleware.func1.1(0x9097c0, 0xc000244000, 0xc00024c000)
        /LambdaRuntimeLocal/lambda/rapi/middleware/middleware.go:66 +0x77
net/http.HandlerFunc.ServeHTTP(0xc00009a2d0, 0x9097c0, 0xc000244000, 0xc00024c000)
        /usr/local/go/src/net/http/server.go:2041 +0x44
github.com/go-chi/chi.(*Mux).ServeHTTP(0xc0000a60c0, 0x9097c0, 0xc000244000, 0xc00024c000)
        /go/pkg/mod/github.com/go-chi/chi@v4.1.2+incompatible/mux.go:70 +0x513
github.com/go-chi/chi.(*Mux).Mount.func1(0x9097c0, 0xc000244000, 0xc00024c000)
        /go/pkg/mod/github.com/go-chi/chi@v4.1.2+incompatible/mux.go:298 +0x118
net/http.HandlerFunc.ServeHTTP(0xc0000943e0, 0x9097c0, 0xc000244000, 0xc00024c000)
        /usr/local/go/src/net/http/server.go:2041 +0x44
github.com/go-chi/chi.(*Mux).routeHTTP(0xc0000a6060, 0x9097c0, 0xc000244000, 0xc00024c000)
        /go/pkg/mod/github.com/go-chi/chi@v4.1.2+incompatible/mux.go:431 +0x278
net/http.HandlerFunc.ServeHTTP(0xc00009c0c0, 0x9097c0, 0xc000244000, 0xc00024c000)
        /usr/local/go/src/net/http/server.go:2041 +0x44
github.com/go-chi/chi.(*Mux).ServeHTTP(0xc0000a6060, 0x9097c0, 0xc000244000, 0xc00017a300)
        /go/pkg/mod/github.com/go-chi/chi@v4.1.2+incompatible/mux.go:86 +0x2b2
net/http.serverHandler.ServeHTTP(0xc0000ac000, 0x9097c0, 0xc000244000, 0xc00017a300)
        /usr/local/go/src/net/http/server.go:2836 +0xa3
net/http.(*conn).serve(0xc000114d20, 0x90a800, 0xc000112680)
        /usr/local/go/src/net/http/server.go:1924 +0x86c
created by net/http.(*Server).Serve
        /usr/local/go/src/net/http/server.go:2962 +0x35c
Exception in thread "main" java.lang.Error: java.net.SocketException: Unexpected end of file from server
        at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:194)
        at lambdainternal.AWSLambda.main(AWSLambda.java:187)
Caused by: java.net.SocketException: Unexpected end of file from server
        at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source)
        at java.base/sun.net.www.http.HttpClient.parseHTTP(Unknown Source)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
        at java.base/java.net.HttpURLConnection.getResponseCode(Unknown Source)
        at lambdainternal.runtimeapi.LambdaRuntimeClient.post(LambdaRuntimeClient.java:81)
        at lambdainternal.runtimeapi.LambdaRuntimeClient.postInitError(LambdaRuntimeClient.java:61)
        at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:231)
        at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:192)
        ... 1 more
time="2021-07-21T06:18:03.878" level=error msg="Init failed" InvokeID= error="Runtime exited with error: exit status 1"
time="2021-07-21T06:18:03.878" level=error msg="INIT DONE failed: Runtime.ExitError"

Java8 of course works:

❯ sam local invoke ClojureOnJava8 
Invoking example.lambda (java8)
Decompressing /home/fierycod/java-11-8-aws-sam-2787/java8.jar
Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-java8:rapid-1.26.0.

Mounting /tmp/tmp5nrm5cyr as /var/task:ro,delegated inside runtime container
START RequestId: 0bd1675d-e6fe-4951-b0c6-14b872aca806 Version: $LATEST
Hello World!
END RequestId: 0bd1675d-e6fe-4951-b0c6-14b872aca806
REPORT RequestId: 0bd1675d-e6fe-4951-b0c6-14b872aca806  Init Duration: 0.21 ms  Duration: 9669.16 ms    Billed Duration: 9700 ms        Memory Size: 2000 MB    Max Memory Used: 2000 MB

Here is the link to the reproduction: https://github.com/FieryCod/java-11-8-aws-sam-2787

[kwojcik-blockether]

@aahung @sriram-mv

I have spoken with Alex Miller (Clojure team) and we've narrowed the issue to Clojure 1.10.1.
Changelog here: https://clojure.org/news/2019/06/06/clojure1-10-1#_java_performance_regression

A possible workaround would be to set the following system property:

-Dclojure.spec.skip-macros=true

Could you please let me know whether this works?

[mndeveci]

Hi @FieryCod ,

I know it is been a while since you've opened this issue, apologies for late reply. I've tried to re-produce the issue by using this repository: https://github.com/FieryCod/java-11-8-aws-sam-2787

When I build and try to locally invoke, I am now getting cyclic dependency error for both java8 and java11.

Caused by: java.lang.Exception: Cyclic load dependency: [ /clojure/spec/alpha ]->/clojure/walk->[ /clojure/spec/alpha ]->/clojure/main->/clojure/core/server
	... 139 more

Is there anything that I need to update from your previous steps to reproduce it?

Thanks!

[mndeveci]

Resolving this issue due to inactivity, please feel free to comment or create new issue if you are still experiencing the problem.