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

Requests and responses seem not to passed correctly when building with GraalVM #2064

Open
k-ogawa-1988 opened this issue Dec 19, 2024 · 0 comments
Labels
type: bug Something isn't working

Comments

@k-ogawa-1988
Copy link

Library Version

graphql-kotlin-spring-server:8.2.1

OS: macOS Sonoma (Apple M1 Pro)
JVM: graalvm-ce-21

Describe the bug

On Spring Boot WebFlux project, GraphQL-Kotlin doesn't receive POST request and send response correctly.

When running example project (attached git repository below) on JVM, it works correctly.
On the other hand, native-compiled binaries doesn't work well.

I'm following this documentation for native build.

To Reproduce

Clone the example project.

Run ./gradlew nativeCompile.

Run ./build/native/nativeCompile/application

Run query below to http://localhost:8080/graphql

query Example{
  listBooks {
    title
  }
}

Debug logs output:

2024-12-19T16:15:47.493+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.buffer.AbstractByteBuf          : -Dio.netty.buffer.checkAccessible: true
2024-12-19T16:15:47.493+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.buffer.AbstractByteBuf          : -Dio.netty.buffer.checkBounds: true
2024-12-19T16:15:47.493+07:00 DEBUG 38715 --- [ctor-http-nio-2] i.n.util.ResourceLeakDetectorFactory     : Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@57cd8bbe
2024-12-19T16:15:47.496+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [a78bb587, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] New http connection, requesting read
2024-12-19T16:15:47.496+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.netty.transport.TransportConfig        : [a78bb587, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2024-12-19T16:15:47.497+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.maxCapacityPerThread: 4096
2024-12-19T16:15:47.497+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.ratio: 8
2024-12-19T16:15:47.497+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.chunkSize: 32
2024-12-19T16:15:47.497+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.blocking: false
2024-12-19T16:15:47.497+07:00 DEBUG 38715 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.batchFastThreadLocalOnly: true
2024-12-19T16:15:47.501+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [a78bb587, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] Increasing pending responses, now 1
2024-12-19T16:15:47.501+07:00 DEBUG 38715 --- [ctor-http-nio-2] reactor.netty.http.server.HttpServer     : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@4ebcaded
2024-12-19T16:15:47.503+07:00 DEBUG 38715 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [a78bb587-1] HTTP POST "/graphql"
2024-12-19T16:15:47.507+07:00 DEBUG 38715 --- [ctor-http-nio-2] o.s.w.r.f.s.s.RouterFunctionMapping      : [a78bb587-1] Mapped to org.springframework.web.reactive.function.server.CoRouterFunctionDsl$CoroutineContextAwareHandlerFunction@455b2e4e
2024-12-19T16:15:47.512+07:00 DEBUG 38715 --- [ctor-http-nio-2] reactor.netty.channel.FluxReceive        : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
2024-12-19T16:15:47.520+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.netty.channel.ChannelOperations        : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] [HttpServer] Channel inbound receiver cancelled (operation cancelled).
2024-12-19T16:15:47.521+07:00 DEBUG 38715 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [a78bb587-1] Completed 400 BAD_REQUEST
2024-12-19T16:15:47.521+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] Last HTTP response frame
2024-12-19T16:15:47.521+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] No sendHeaders() called before complete, sending zero-length header
2024-12-19T16:15:47.521+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] Decreasing pending responses, now 0
2024-12-19T16:15:47.521+07:00 DEBUG 38715 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [a78bb587-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63600] Last HTTP packet was sent, terminating the channel

Also, GraphiQL doesn't work because resource not found.


Note that if you run with GET request below, it seems running but empty response will be returned.

curl -s -X GET -H "Content-Type: application/json" 'http://localhost:8080/graphql?query=%7BlistBooks%7Btitle%7D%7D'

Debug logs output:

2024-12-19T16:13:47.411+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.n.http.server.HttpServerOperations     : [cc361c26, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] New http connection, requesting read
2024-12-19T16:13:47.411+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.netty.transport.TransportConfig        : [cc361c26, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2024-12-19T16:13:47.413+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.n.http.server.HttpServerOperations     : [cc361c26, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] Increasing pending responses, now 1
2024-12-19T16:13:47.413+07:00 DEBUG 30907 --- [ctor-http-nio-5] reactor.netty.http.server.HttpServer     : [cc361c26-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@35264d81
2024-12-19T16:13:47.413+07:00 DEBUG 30907 --- [ctor-http-nio-5] o.s.w.s.adapter.HttpWebHandlerAdapter    : [cc361c26-3] HTTP GET "/graphql?query=%7BlistBooks%7Btitle%7D%7D"
2024-12-19T16:13:47.413+07:00 DEBUG 30907 --- [ctor-http-nio-5] o.s.w.r.f.s.s.RouterFunctionMapping      : [cc361c26-3] Mapped to org.springframework.web.reactive.function.server.CoRouterFunctionDsl$CoroutineContextAwareHandlerFunction@1b2c0b20
2024-12-19T16:13:47.418+07:00 DEBUG 30907 --- [ctor-http-nio-5] notprivacysafe.graphql.GraphQL           : Executing request. operation name: 'null'. query: '{listBooks{title}}'. variables '{}'
2024-12-19T16:13:47.418+07:00 DEBUG 30907 --- [ctor-http-nio-5] notprivacysafe.graphql.GraphQL           : Parsing query: '{listBooks{title}}'...
2024-12-19T16:13:47.418+07:00 DEBUG 30907 --- [ctor-http-nio-5] notprivacysafe.graphql.GraphQL           : Validating query: '{listBooks{title}}'
2024-12-19T16:13:47.418+07:00 DEBUG 30907 --- [ctor-http-nio-5] notprivacysafe.graphql.GraphQL           : Executing 'b2e2888e-0134-4852-8892-567d877e673d'. operation name: 'null'. query: '{listBooks{title}}'. variables '{}'
2024-12-19T16:13:47.420+07:00 DEBUG 30907 --- [ctor-http-nio-5] n.graphql.execution.Execution            : Executing 'b2e2888e-0134-4852-8892-567d877e673d' query operation: 'QUERY' using 'graphql.execution.AsyncExecutionStrategy' execution strategy
2024-12-19T16:13:47.420+07:00 DEBUG 30907 --- [ctor-http-nio-5] .i.d.DataLoaderDispatcherInstrumentation : Dispatching data loaders ([AuthorDataLoader])
2024-12-19T16:13:47.420+07:00 DEBUG 30907 --- [ctor-http-nio-5] graphql.execution.ExecutionStrategy      : 'b2e2888e-0134-4852-8892-567d877e673d' completing field '/listBooks'...
2024-12-19T16:13:47.421+07:00 DEBUG 30907 --- [ctor-http-nio-5] graphql.execution.ExecutionStrategy      : 'b2e2888e-0134-4852-8892-567d877e673d' completing field '/listBooks[0]/title'...
2024-12-19T16:13:47.421+07:00 DEBUG 30907 --- [ctor-http-nio-5] graphql.execution.ExecutionStrategy      : 'b2e2888e-0134-4852-8892-567d877e673d' completing field '/listBooks[1]/title'...
2024-12-19T16:13:47.421+07:00 DEBUG 30907 --- [ctor-http-nio-5] graphql.execution.ExecutionStrategy      : 'b2e2888e-0134-4852-8892-567d877e673d' completing field '/listBooks[2]/title'...
2024-12-19T16:13:47.421+07:00 DEBUG 30907 --- [ctor-http-nio-5] .i.d.DataLoaderDispatcherInstrumentation : Dispatching data loaders ([AuthorDataLoader])
2024-12-19T16:13:47.422+07:00 DEBUG 30907 --- [ctor-http-nio-5] graphql.GraphQL                          : Execution 'b2e2888e-0134-4852-8892-567d877e673d' completed with zero errors
2024-12-19T16:13:47.422+07:00 DEBUG 30907 --- [ctor-http-nio-5] o.s.http.codec.json.Jackson2JsonEncoder  : [cc361c26-3] Encoding [GraphQLResponse(data={listBooks=[{title=Flowers to Algernon}, {title=The Catcher in the Rye}, {title (truncated)...]
2024-12-19T16:13:47.422+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.n.http.server.HttpServerOperations     : [cc361c26-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] Decreasing pending responses, now 0
2024-12-19T16:13:47.424+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.n.http.server.HttpServerOperations     : [cc361c26-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] Last HTTP packet was sent, terminating the channel
2024-12-19T16:13:47.424+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.netty.channel.ChannelOperations        : [cc361c26-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] [HttpServer] Channel inbound receiver cancelled (operation cancelled).
2024-12-19T16:13:47.424+07:00 DEBUG 30907 --- [ctor-http-nio-5] o.s.w.s.adapter.HttpWebHandlerAdapter    : [cc361c26-3] Completed 200 OK
2024-12-19T16:13:47.424+07:00 DEBUG 30907 --- [ctor-http-nio-5] r.n.http.server.HttpServerOperations     : [cc361c26-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63425] Last HTTP response frame

Expected behavior

Works correctly same as running on JVM.

@k-ogawa-1988 k-ogawa-1988 added the type: bug Something isn't working label Dec 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug Something isn't working
Development

No branches or pull requests

1 participant