John-Paul-R commented 3 years ago

Issue Outline

Certain GraphQL queries respond with an error when issued for the first time within a certain timespan.

This is an issue I encountered recently, and still have relatively little information at present. I generally encounter it the first time I make a certain GraphQL request on a day, ~~but not on the second and later attempts.~~ (Edit: upon further inspection, this is inconsistent.)

I conducted a brief series of tests today in an effort to pin how long after the first (errored) response is received that the error starts to appear again.

A request made approx 1 min after the initial errored response received a successful response.
A request made approx 10 min after the initial errored response received an errored response.
A request made approx 11 min after the initial errored response (approx 1 min after previous) received an errored response.
A request made approx 30 min after the initial errored response (approx 20 min after previous) received a successful response.
A request made approx 35 min after the initial errored response (approx 5 min after previous) received a successful response.

To be fair, I'm not 100% certain that the issue is related to the amount of time between requests, but, in my experience, the error happens much more often the first time I make a request in a day. (Although this could be sample size, as I first noticed the issue about a week ago.)

Steps to reproduce

This isn't incredibly specific at the moment. I can try to narrow it down a bit more if necessary, but it's a strange process because I'm not 100% certain of the time interval I need to wait to be sure that the conditions needed for the error to occur are met (if it's even actually related to the time between requests).

My Request

My GraphQL request was sent as a POST request to https://curse.nikky.moe/graphql with these headers... 'Content-Type': 'application/json', 'Accept': 'application/json' ...and with this as the contents.

{
  addons(gameId: 432, category: "Fabric") {
    id
    name
    slug
    summary
    categories {
      categoryId
      name
    }
    authors {
      id
      name
      url
    }
    dateReleased
    dateModified
    downloadCount
    files {
      displayName
      gameVersion
    }
  }
}

Errored response

The error that occurs for the first request made within a certain time interval. (Reformatted a bit for readability)

{
  "exception" : "kotlin.KotlinNullPointerException",
  "message" : "",
  "stacktrace" : [
    "kotlin.KotlinNullPointerException", 
      "\tat moe.nikky.curseproxy.graphql.AppSchema$schema$1$6$2$1.invokeSuspend(AppSchema.kt:161)", 
      "\tat \b\b\b(Coroutine boundary.\b(\b)", 
      "\tat com.apurebase.kgraphql.ExtensionsKt$toMapAsync$2.invokeSuspend(Extensions.kt:56)", 
      "\tat com.apurebase.kgraphql.schema.execution.ParallelRequestExecutor.createNode(ParallelRequestExecutor.kt:125)", 
      "\tat com.apurebase.kgraphql.schema.execution.ParallelRequestExecutor.writeOperation(ParallelRequestExecutor.kt:86)", 
      "\tat com.apurebase.kgraphql.schema.execution.ParallelRequestExecutor$suspendExecute$2$resultMap$1.invokeSuspend(ParallelRequestExecutor.kt:59)", 
      "\tat com.apurebase.kgraphql.ExtensionsKt$toMapAsync$2.invokeSuspend(Extensions.kt:56)", 
      "\tat com.apurebase.kgraphql.schema.execution.ParallelRequestExecutor$suspendExecute$2.invokeSuspend(ParallelRequestExecutor.kt:53)", 
      "\tat com.apurebase.kgraphql.schema.execution.ParallelRequestExecutor.suspendExecute(ParallelRequestExecutor.kt:49)", 
      "\tat com.apurebase.kgraphql.schema.DefaultSchema$execute$2.invokeSuspend(DefaultSchema.kt:53)", 
      "\tat moe.nikky.curseproxy.GraphQLRoutesKt$graphql$1$1.invokeSuspend(GraphQLRoutes.kt:39)", 
      "\tat io.ktor.routing.Routing.executeResult(Routing.kt:147)", 
      "\tat io.ktor.routing.Routing.interceptor(Routing.kt:34)", 
      "\tat io.ktor.routing.Routing$Feature$install$1.invokeSuspend(Routing.kt:99)", 
      "\tat io.ktor.features.ContentNegotiation$Feature$install$1.invokeSuspend(ContentNegotiation.kt:107)", 
      "\tat io.ktor.features.StatusPages$interceptCall$2.invokeSuspend(StatusPages.kt:101)", 
      "\tat io.ktor.features.StatusPages.interceptCall(StatusPages.kt:100)", 
      "\tat io.ktor.features.StatusPages$Feature$install$2.invokeSuspend(StatusPages.kt:140)", 
      "\tat io.ktor.features.CallLogging$Feature$install$1$invokeSuspend$$inlined$withMDC$1.invokeSuspend(CallLogging.kt:226)", 
      "\tat io.ktor.features.CallLogging$Feature$install$1.invokeSuspend(CallLogging.kt:230)", 
      "\tat io.ktor.server.engine.DefaultEnginePipelineKt$defaultEnginePipeline$2.invokeSuspend(DefaultEnginePipeline.kt:120)", 
      "\tat io.ktor.server.netty.NettyApplicationCallHandler$handleRequest$1.invokeSuspend(NettyApplicationCallHandler.kt:40)",
    "Caused by: kotlin.KotlinNullPointerException", 
      "\tat moe.nikky.curseproxy.graphql.AppSchema$schema$1$6$2$1.invokeSuspend(AppSchema.kt:161)", 
      "\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)", 
      "\tat kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:56)", 
      "\tat kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)", 
      "\tat kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:738)", 
      "\tat kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)", 
      "\tat kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)", "" ]
}

Successful response

As far as I can tell, the response to a request made shortly after the initial errored response is completely successful and returns the expected data. You can view one of these successful responses at this link (it's big (2.8 MB)).

John-Paul-R commented 3 years ago

Have not encountered this issue in over 2 weeks. Closing issue.

makamys commented 2 years ago

This has been happening again for me since around 2022-01-08. Large requests fail with this error about half the time, but the same request succeeds after trying again enough times. It seems failure is more likely the more complex the query is.

Tests

I made various queries 10 times in a row as an experiment.

1. Many mods, many fields

Query 1

```graphiql { addons(gameId: 432, section: "Mods", idList: [342543, 32274, 296468, 557076, 416796, 363553, 562211, 483885, 495153, 71738, 548411, 532554, 388172, 550476, 368718, 312918, 367706, 239197, 398430, 404578, 418915, 398438, 538214, 339561, 547434, 565866, 503922, 543863, 545405, 391298, 375427, 289412, 266890, 565902, 357008, 227985, 545946, 565405, 537253, 316582, 420519, 557735, 545459, 237749, 317121, 267458, 359619, 527558, 405703, 561868, 261837, 286924, 223439, 564941, 465109, 404183, 561885, 391390, 438496, 269024, 454372, 406756, 500456, 565486, 403185, 263420, 537853, 245506, 534281, 565005, 511254, 353051, 379680, 556331, 539957, 256822, 457015, 548152, 564029, 558914, 396099, 510278, 402256, 317780, 463703, 416089, 363363, 385891, 395620, 565095, 565100, 390007, 334204, 399747, 513924, 395653, 313219, 549264, 537490, 561046, 558998, 501658, 325020, 404380, 514465, 493490, 378802, 532403, 562109, 535489, 565703, 472521, 457676, 559053, 565200, 566242, 554992, 561648, 496631]) { id name slug summary categories { categoryId } authors { id name } dateReleased dateModified downloadCount files { id gameVersion fileDate } } } ```

Returns a 1.61 MB response which took 9~20s, and succeeded 6/10 times.

2. Many mods, one field

Removing all fields other than dateModified...

Query 2

```graphiql { addons(gameId: 432, section: "Mods", idList: [342543, 32274, 296468, 557076, 416796, 363553, 562211, 483885, 495153, 71738, 548411, 532554, 388172, 550476, 368718, 312918, 367706, 239197, 398430, 404578, 418915, 398438, 538214, 339561, 547434, 565866, 503922, 543863, 545405, 391298, 375427, 289412, 266890, 565902, 357008, 227985, 545946, 565405, 537253, 316582, 420519, 557735, 545459, 237749, 317121, 267458, 359619, 527558, 405703, 561868, 261837, 286924, 223439, 564941, 465109, 404183, 561885, 391390, 438496, 269024, 454372, 406756, 500456, 565486, 403185, 263420, 537853, 245506, 534281, 565005, 511254, 353051, 379680, 556331, 539957, 256822, 457015, 548152, 564029, 558914, 396099, 510278, 402256, 317780, 463703, 416089, 363363, 385891, 395620, 565095, 565100, 390007, 334204, 399747, 513924, 395653, 313219, 549264, 537490, 561046, 558998, 501658, 325020, 404380, 514465, 493490, 378802, 532403, 562109, 535489, 565703, 472521, 457676, 559053, 565200, 566242, 554992, 561648, 496631]) { dateModified } } ```

Returns an 8 KB response which took 0.24~0.5s, and succeeded 10/10 times.

3. One mod, many fields

Keeping all the fields, but only the first mod...

Query 3

```graphiql { addons(gameId: 432, section: "Mods", idList: [342543]) { id name slug summary categories { categoryId } authors { id name } dateReleased dateModified downloadCount files { id gameVersion fileDate } } } ```

Returns a 75 KB response which took 3~20 seconds, and succeeded 5/10 times.

NikkyAI / CurseProxy

Certain GraphQL queries respond with an error when issued for the first time within a certain timespan. #3