Graal: Regression with Micronaut and Freemarker: NPE

[ilopmar]

Our CI has detected a regression in this commit: https://github.com/oracle/graal/commit/7ea083dd1132c715100329309d72c6699015144d

It is still possible to create the native image but when starting it and sending a request there is a NPE. See error bellow.

Steps to reproduce the issue:

• git clone https://github.com/micronaut-graal-tests/micronaut-views-graal
• cd micronaut-views-graal
• git checkout freemarker
• Use GraalVM built from master, specifically the commit linked before.
• ./build-native-image.sh
• Start the native-image and send a request:
  curl localhost:8080/views/freemarker-view

I have also tried adding --initialize-at-run-time=io.netty.buffer.AbstractReferenceCountedByteBuf as suggested in #1315 but the error is the same.

Error:

$ ./views-graal-freemarker
09:47:06.345 [main] DEBUG i.m.web.router.DefaultRouteBuilder - Created Route: GET /views/freemarker -> ViewsController#ModelAndView freemaker() (application/json )
09:47:06.345 [main] DEBUG i.m.web.router.DefaultRouteBuilder - Created Route: HEAD /views/freemarker -> ViewsController#ModelAndView freemaker() (application/json )
09:47:06.345 [main] DEBUG i.m.web.router.DefaultRouteBuilder - Created Route: GET /views/freemarker-view -> ViewsController#HttpResponse freemakerPojoView() (application/json )
09:47:06.345 [main] DEBUG i.m.web.router.DefaultRouteBuilder - Created Route: HEAD /views/freemarker-view -> ViewsController#HttpResponse freemakerPojoView() (application/json )
09:47:06.358 [main] INFO  io.micronaut.runtime.Micronaut - Startup completed in 69ms. Server Running: http://localhost:8080
09:47:09.846 [pool-2-thread-2] ERROR i.m.h.s.netty.RoutingInBoundHandler - Unexpected error occurred: null
java.lang.NullPointerException: null
    at freemarker.core.DollarVariable.<init>(DollarVariable.java:53)
    at freemarker.core.FMParser.StringOutput(FMParser.java:1564)
    at freemarker.core.FMParser.MixedContentElements(FMParser.java:3761)
    at freemarker.core.FMParser.If(FMParser.java:1663)
    at freemarker.core.FMParser.FreemarkerDirective(FMParser.java:3422)
    at freemarker.core.FMParser.MixedContentElements(FMParser.java:3812)
    at freemarker.core.FMParser.Root(FMParser.java:4458)
    at freemarker.template.Template.<init>(Template.java:253)
    at freemarker.cache.TemplateCache.loadTemplate(TemplateCache.java:549)
    at freemarker.cache.TemplateCache.getTemplateInternal(TemplateCache.java:439)
    at freemarker.cache.TemplateCache.getTemplate(TemplateCache.java:292)
    at freemarker.template.Configuration.getTemplate(Configuration.java:2750)
    at freemarker.template.Configuration.getTemplate(Configuration.java:2599)
    at io.micronaut.views.freemarker.FreemarkerViewsRenderer.exists(FreemarkerViewsRenderer.java:86)
    at io.micronaut.views.ViewsFilter.lambda$doFilter$0(ViewsFilter.java:130)
    at io.reactivex.internal.operators.flowable.FlowableSwitchMap$SwitchMapSubscriber.onNext(FlowableSwitchMap.java:113)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.lambda$onNext$0(InstrumentedSubscriber.java:80)
    at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:52)
    at io.micronaut.http.context.ServerRequestContext.lambda$instrument$0(ServerRequestContext.java:68)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onNext(InstrumentedSubscriber.java:84)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.lambda$onNext$0(InstrumentedSubscriber.java:80)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onNext(InstrumentedSubscriber.java:84)
    at io.reactivex.internal.operators.flowable.FlowableSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FlowableSwitchIfEmpty.java:59)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.lambda$onNext$0(InstrumentedSubscriber.java:80)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onNext(InstrumentedSubscriber.java:84)
    at io.reactivex.internal.operators.flowable.FlowableMap$MapSubscriber.onNext(FlowableMap.java:68)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.lambda$onNext$0(InstrumentedSubscriber.java:80)
    at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onNext(InstrumentedSubscriber.java:84)
    at io.reactivex.internal.operators.flowable.FlowableCreate$NoOverflowBaseAsyncEmitter.onNext(FlowableCreate.java:403)
    at io.micronaut.http.server.netty.RoutingInBoundHandler.lambda$buildResultEmitter$19(RoutingInBoundHandler.java:1430)
    at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:37)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.internal.operators.flowable.FlowableSwitchIfEmpty.subscribeActual(FlowableSwitchIfEmpty.java:32)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.internal.operators.flowable.FlowableSwitchMap.subscribeActual(FlowableSwitchMap.java:49)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14776)
    at io.micronaut.http.context.ServerRequestTracingPublisher.lambda$subscribe$0(ServerRequestTracingPublisher.java:52)
    at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:52)
    at io.micronaut.http.context.ServerRequestTracingPublisher.subscribe(ServerRequestTracingPublisher.java:52)
    at io.reactivex.internal.operators.flowable.FlowableFromPublisher.subscribeActual(FlowableFromPublisher.java:29)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14826)
    at io.reactivex.Flowable.subscribe(Flowable.java:14773)
    at io.reactivex.internal.operators.flowable.FlowableSubscribeOn$SubscribeOnSubscriber.run(FlowableSubscribeOn.java:82)
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:288)
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:253)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:476)
    at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)

[thomaswue]

Thanks for this detailed report. Could reproduce and have a change that fixes the problem. Need to verify that the fix doesn't have a negative performance impact; and that there are no related issues left unaddressed.

[ilopmar]

Thanks @thomaswue. Happy to test the fix once it's committed to master branch :)

[thomaswue]

This commit should have fixed it: https://github.com/oracle/graal/commit/546b7bdef0fff923626fbf405fb7acdfda5d1fc3

Can you confirm?

[ilopmar]

Yes, it works. Thank you very much! :)

[thomaswue]

Excellent, thank you!