search

micronaut-projects / micronaut-core

Micronaut Application Framework
http://micronaut.io
Apache License 2.0
6.05k stars 1.06k forks source link

POSTing to any path error-loops in JaxbAnnotationIntrospector on native-image of complex application #2611

Closed doctorpangloss closed 4 years ago

doctorpangloss commented 4 years ago

Task List

Summary

A complex project throws an exception in the JaxbAnnotationIntrospector class when a POST request is made, regardless to which path that POST is made. The complexity of the project may be a red herring.

Background

Spellsource is a video game server. Graal and Micronaut are being investigated to support Spellsource's computer opponent's AI move computation, deploying it as a serverless / lambda function instead of running in the same JVM as the rest of the multiplayer services to reduce memory usage.

To do this, it is using Micronaut as the harness around the code that actually computes the computer opponent's moves.

There are three interacting parts that probably contribute to this error:

The project is used in production for a few years now and has a healthy and active user community. Spellsource is developed by Hidden Switch, an experimental game studio. We take pride in trying out new technologies and we have a long history with Java as a games backend.

Expected Behaviour

The request should succeed like it does in the tests without native-image. Simply run gradle micro:test to verify this behaviour.

Actual Behaviour

CURL-ing a native-image built docker container will instead cause a repeating exception and a hung server.

Environment Information

Example Application

https://github.com/hiddenswitch/Spellsource-Server.git

Steps to Reproduce

Clone the repository. with git clone https://github.com/hiddenswitch/Spellsource-Server.git. In its root...

➜  Spellsource-Server git:(master) ✗ sdk use java 19.3.0.2.r11-grl

Using java version 19.3.0.2.r11-grl in this shell.
➜  Spellsource-Server git:(master) ✗ gradle clean
(omitted)
BUILD SUCCESSFUL in 2s
12 actionable tasks: 11 executed, 1 up-to-date
➜  Spellsource-Server git:(master) ✗ gradle micro:shadowJar && cd micro && ./docker-build.sh
(omitted)
BUILD SUCCESSFUL in 25s
17 actionable tasks: 17 executed
Sending build context to Docker daemon  31.59MB
Step 1/9 : FROM oracle/graalvm-ce:19.3.0-java11 as graalvm
 ---> bc6f2b723104
Step 2/9 : RUN gu install native-image
 ---> Using cache
 ---> c2f199532a82
Step 3/9 : COPY . /home/app/micro
 ---> 2909368fd248
Step 4/9 : WORKDIR /home/app/micro
 ---> Running in bd9d9784164e
Removing intermediate container bd9d9784164e
 ---> 277f0255bd11
Step 5/9 : RUN native-image --no-server --no-fallback --initialize-at-build-time --static -cp build/libs/micro-*-all.jar
 ---> Running in fa86eb92464d
[micro:24]    classlist:  16,194.53 ms
[micro:24]        (cap):   1,070.28 ms
[micro:24]        setup:   3,226.22 ms
[micro:24]   (typeflow): 514,885.51 ms
[micro:24]    (objects): 407,097.50 ms
[micro:24]   (features):  14,853.57 ms
[micro:24]     analysis: 966,316.06 ms
[micro:24]     (clinit):  33,616.52 ms
[micro:24]     universe: 198,027.51 ms
[micro:24]      (parse):  25,512.07 ms
[micro:24]     (inline):  93,047.52 ms
[micro:24]    (compile): 194,925.61 ms
[micro:24]      compile: 352,494.73 ms
[micro:24]        image:  17,985.35 ms
[micro:24]        write:   3,541.60 ms
[micro:24]      [total]: 1,559,031.20 ms
Removing intermediate container fa86eb92464d
 ---> 03000bc5d460
Step 6/9 : FROM scratch
 ---> 
Step 7/9 : EXPOSE 8080
 ---> Using cache
 ---> 7bc9a731f96d
Step 8/9 : COPY --from=graalvm /home/app/micro/micro /app/micro
 ---> 23e9d7bdc21c
Step 9/9 : ENTRYPOINT ["/app/micro", "-Djava.library.path=/app"]
 ---> Running in 651d7f5f7e62
Removing intermediate container 651d7f5f7e62
 ---> 5e51265eec23
Successfully built 5e51265eec23
Successfully tagged micro:latest

To run the docker container execute:
    $ docker run -p 8080:8080 micro
➜  micro git:(master) ✗ docker run -p 8080:8080 micro
23:47:52.947 [main] INFO  io.micronaut.runtime.Micronaut - Startup completed in 47ms. Server Running: http://8849077ae78c:8080

Executing the exact curl request from tests:

curl -X POST -d '{\
  "playerId": -1,\
  "trace": {\
    "seed": -4961240650166496536,\
    "catalogueVersion": 2,\
    "heroClasses": [\
      "OBSIDIAN",\
      "BLOOD"\
    ],\
    "deckCardIds": [\
      {\
        "playerId": 0,\
        "cardIds": [\
          "minion_nightmare_dragon",\
          "minion_flesh_monstrosity",\
          "minion_darkbent_drake",\
          "minion_anarking",\
          "minion_dragonfruit_whelp",\
          "spell_collectible_army_of_the_dead",\
          "minion_glass_memory_golem",\
          "minion_gustbreaker",\
          "weapon_ashbringer_corrupted",\
          "minion_echoweb_lurker",\
          "minion_plagueborn_meatwall",\
          "minion_plagueborn_meatwall",\
          "minion_marrowling",\
          "minion_shadowveiler",\
          "minion_jungle_king",\
          "spell_dk_corpse_explosion",\
          "minion_rotting_dead",\
          "minion_magic_muffler",\
          "minion_stowaway_scoundrel",\
          "minion_savage_sprite",\
          "minion_teron_gorefiend",\
          "minion_stalwart_sculptor",\
          "spell_outbreak",\
          "minion_flesh_monstrosity",\
          "spell_collectible_doom_pact",\
          "minion_hypothermic_outcast",\
          "minion_jungle_king",\
          "minion_sacred_tombstone",\
          "minion_wild_pyrodancer",\
          "minion_natural_convert"\
        ]\
      },\
      {\
        "playerId": 1,\
        "cardIds": [\
          "minion_infinite_futurist",\
          "minion_dimensional_courier",\
          "weapon_heartpiercer",\
          "minion_hypnotist",\
          "minion_jack_in_the_box",\
          "minion_colrum",\
          "spell_take_flight",\
          "minion_dragonling_pet",\
          "minion_gentleman_s_giant",\
          "minion_bronze_warden",\
          "spell_twilight_ritual",\
          "spell_hemoshape_blade",\
          "minion_starving_vampire",\
          "spell_hemoshape_brand",\
          "minion_lord_cookie",\
          "minion_fairytale_tracker",\
          "minion_sky_high_surveyor",\
          "minion_barside_slinker",\
          "minion_gentleman_s_giant",\
          "minion_hungering_acolyte",\
          "spell_lunar_infusion",\
          "minion_starving_vampire",\
          "minion_deep_borer",\
          "minion_gemstone_giant",\
          "spell_proselytize",\
          "minion_hungering_acolyte",\
          "minion_deepwood_barghest",\
          "minion_the_imperial_soul",\
          "minion_demonic_frontrunner",\
          "minion_furious_fiend"\
        ]\
      }\
    ],\
    "deckFormatName": "Spellsource",\
    "deckFormatSets": [\
      "VERDANT_DREAMS",\
      "SANDS_OF_TIME",\
      "BATTLE_FOR_ASHENVALE",\
      "CUSTOM",\
      "SPELLSOURCE_BASIC"\
    ],\
    "secondPlayerBonusCards": [\
      "spell_lunstone"\
    ],\
    "mulligans": [\
      {\
        "playerId": 0,\
        "entityIds": [\
          28,\
          24\
        ]\
      },\
      {\
        "playerId": 1,\
        "entityIds": [\
          56\
        ]\
      }\
    ],\
    "actions": [\
    ],\
    "id": null,\
    "traceErrors": false\
  }\
}' http://localhost:8080/bots/request

Repeating error in the docker container (you will have to stop the container with docker stop):

23:48:06.486 [nioEventLoopGroup-2-2] ERROR i.m.h.s.netty.RoutingInBoundHandler - Unexpected error occurred: null
java.lang.NullPointerException: null
    at jdk.internal.loader.BootLoader.loadClassOrNull(BootLoader.java:116)
    at jdk.internal.loader.BootLoader.loadClass(BootLoader.java:124)
    at java.lang.Package.getPackageInfo(Package.java:422)
    at java.lang.Package.getAnnotation(Package.java:441)
    at com.fasterxml.jackson.module.jaxb.JaxbAnnotationIntrospector.findAnnotation(JaxbAnnotationIntrospector.java:1291)
    at com.fasterxml.jackson.module.jaxb.JaxbAnnotationIntrospector.findAccessType(JaxbAnnotationIntrospector.java:571)
    at com.fasterxml.jackson.module.jaxb.JaxbAnnotationIntrospector.findAutoDetectVisibility(JaxbAnnotationIntrospector.java:522)
    at com.fasterxml.jackson.databind.introspect.AnnotationIntrospectorPair.findAutoDetectVisibility(AnnotationIntrospectorPair.java:212)
    at com.fasterxml.jackson.databind.introspect.AnnotationIntrospectorPair.findAutoDetectVisibility(AnnotationIntrospectorPair.java:211)
    at com.fasterxml.jackson.databind.cfg.MapperConfigBase.getDefaultVisibilityChecker(MapperConfigBase.java:700)
    at com.fasterxml.jackson.databind.introspect.POJOPropertiesCollector.<init>(POJOPropertiesCollector.java:142)
    at com.fasterxml.jackson.databind.introspect.BasicClassIntrospector.constructPropertyCollector(BasicClassIntrospector.java:212)
    at com.fasterxml.jackson.databind.introspect.BasicClassIntrospector.collectProperties(BasicClassIntrospector.java:190)
    at com.fasterxml.jackson.databind.introspect.BasicClassIntrospector.forSerialization(BasicClassIntrospector.java:92)
    at com.fasterxml.jackson.databind.introspect.BasicClassIntrospector.forSerialization(BasicClassIntrospector.java:16)
    at com.fasterxml.jackson.databind.SerializationConfig.introspect(SerializationConfig.java:851)
    at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.createSerializer(BeanSerializerFactory.java:135)
    at com.fasterxml.jackson.databind.SerializerProvider._createUntypedSerializer(SerializerProvider.java:1388)
    at com.fasterxml.jackson.databind.SerializerProvider._createAndCacheUntypedSerializer(SerializerProvider.java:1336)
    at com.fasterxml.jackson.databind.SerializerProvider.findValueSerializer(SerializerProvider.java:510)
    at com.fasterxml.jackson.databind.SerializerProvider.findTypedValueSerializer(SerializerProvider.java:713)
    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:308)
    at com.fasterxml.jackson.databind.ObjectMapper._configAndWriteValue(ObjectMapper.java:4094)
    at com.fasterxml.jackson.databind.ObjectMapper.writeValueAsBytes(ObjectMapper.java:3428)
    at io.micronaut.jackson.codec.JacksonMediaTypeCodec.encode(JacksonMediaTypeCodec.java:183)
    at io.micronaut.jackson.codec.JacksonMediaTypeCodec.encode(JacksonMediaTypeCodec.java:192)
    at io.micronaut.http.server.netty.RoutingInBoundHandler.encodeBodyAsByteBuf(RoutingInBoundHandler.java:1400)
    at io.micronaut.http.server.netty.RoutingInBoundHandler.encodeBodyWithCodec(RoutingInBoundHandler.java:1346)
    at io.micronaut.http.server.netty.RoutingInBoundHandler.lambda$subscribeToResponsePublisher$12(RoutingInBoundHandler.java:1274)
    at io.reactivex.internal.operators.flowable.FlowableMap$MapSubscriber.onNext(FlowableMap.java:63)
    at io.reactivex.internal.operators.flowable.FlowableSubscribeOn$SubscribeOnSubscriber.onNext(FlowableSubscribeOn.java:97)
    at io.micronaut.http.context.ServerRequestTracingPublisher$1.lambda$onNext$1(ServerRequestTracingPublisher.java:60)
    at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:68)
    at io.micronaut.http.context.ServerRequestTracingPublisher$1.onNext(ServerRequestTracingPublisher.java:60)
    at io.micronaut.http.context.ServerRequestTracingPublisher$1.onNext(ServerRequestTracingPublisher.java:52)
    at io.reactivex.internal.util.HalfSerializer.onNext(HalfSerializer.java:45)
    at io.reactivex.internal.subscribers.StrictSubscriber.onNext(StrictSubscriber.java:97)
    at io.micronaut.reactive.rxjava2.RxInstrumentedSubscriber.onNext(RxInstrumentedSubscriber.java:70)
    at io.reactivex.internal.subscriptions.ScalarSubscription.request(ScalarSubscription.java:55)
    at io.reactivex.internal.subscriptions.SubscriptionHelper.deferredSetOnce(SubscriptionHelper.java:202)
    at io.reactivex.internal.subscribers.StrictSubscriber.onSubscribe(StrictSubscriber.java:87)
    at io.micronaut.reactive.rxjava2.RxInstrumentedSubscriber.onSubscribe(RxInstrumentedSubscriber.java:55)
    at io.reactivex.internal.operators.flowable.FlowableJust.subscribeActual(FlowableJust.java:34)
    at io.reactivex.Flowable.subscribe(Flowable.java:14918)
    at io.reactivex.Flowable.subscribe(Flowable.java:14868)
    at io.micronaut.http.context.ServerRequestTracingPublisher.lambda$subscribe$0(ServerRequestTracingPublisher.java:52)
    at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:68)
    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:14918)
    at io.reactivex.Flowable.subscribe(Flowable.java:14865)
    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 io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:510)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:518)
    at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:834)
    at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:479)
    at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)
graemerocher commented 4 years ago

Looks like something in Jackson is triggering the need for reflection. Will investigate, thanks. In the meantime you can probably workaround by running the tracing agent on the project to identify what is using reflection. See https://medium.com/graalvm/introducing-the-tracing-agent-simplifying-graalvm-native-image-configuration-c3b56c486271

doctorpangloss commented 4 years ago

Tracing didn't change the story here unfortunately.

I'm getting this error posting to paths that just return and accept nothing. Also, I'm not sure why it's trying to encode JSON here, in a request, it hasn't gotten to the writing response part. It seems like there is a lot of indirection. I am trying now with RC1. But I think there's a lot that might be buggy with Introspection and Jackson.

graemerocher commented 4 years ago

If you can isolate it to a smaller easy to reproduce example app we can take a look

graemerocher commented 4 years ago

PS it seems to be caused by the fact that the app has the JAXB module on the classpath https://github.com/FasterXML/jackson-modules-base/tree/master/jaxb

Which frankly we have not tested not supported so far on GraalVM

doctorpangloss commented 4 years ago

This seems to have fixed the issue:

var application = Micronaut.run(Application.class);
var objectMapper = application.getBean(ObjectMapper.class);
objectMapper.setAnnotationIntrospector(new JacksonAnnotationIntrospector());

This basically removes the JaxB annotation inspector that the error message is telling us about. I'm not sure how it gets in there though, I think that's the bug.

I'll post a clear reproduction.

doctorpangloss commented 4 years ago

I'm getting closer to the underlying issue. It may be related to Graal's tracing agent putting service loader definitions in for the JaxB annotation processor.

{"pattern":"META-INF/services/com.fasterxml.jackson.databind.Module"}
doctorpangloss commented 4 years ago

The solution I posted here https://github.com/micronaut-projects/micronaut-core/issues/2611#issuecomment-583180870 will be sufficient for me!