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

@SchemaMapping may cause the order to be disrupted. How to solve it #949

Open
madwind opened this issue Apr 13, 2024 · 14 comments
Open

@SchemaMapping may cause the order to be disrupted. How to solve it #949

madwind opened this issue Apr 13, 2024 · 14 comments
Labels
status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged

Comments

@madwind
Copy link

madwind commented Apr 13, 2024

I have a list sorted by vodtime. When I use @schemamapping, I find that if the return type is Mono, it causes the order to be disrupted.

    searchVideo(searchParams: $searchParams){
      id
      uniqueName
      vodName
      vodYear
      typeName
      vodArea
      vodPics <= SchemaMapping
      vodRemarks
      vodDoubanScore
      vodDoubanId
      vodTime
      lastEpisode <= SchemaMapping
      resources <= SchemaMapping
      isFavorite <= SchemaMapping Mono
    }
    @SubscriptionMapping
    public Flux<Video> searchVideo(@Argument SearchParamsDTO searchParams, @AuthenticationPrincipal User user) {
        return videoService.listVideos(searchParams).doOnNext(video -> System.out.println(video.getVodTime()));
    }

    @SchemaMapping
    public Mono<Boolean> isFavorite(Video video, @AuthenticationPrincipal User user) {
        return favoriteRepository.findByUserIdAndVideoUniqueName(user.getId(), video.getUniqueName())
                .hasElement();
    }

    @SchemaMapping
    public List<String> vodPics(Video video) {
        return video
                .getPlaySources()
                .stream()
                .map(PlaySource::getVodPic)
                .filter(StringUtils::hasText)
                .collect(Collectors.toList());
    }

ts:

console.log("vodTime: " + video.vodTime + ", isFavorite: " + video.isFavorite)

java log:

2024-04-13 09:35:41
2024-04-13 09:35:15
2024-04-13 09:34:02
2024-04-13 09:26:40
2024-04-13 09:26:14
2024-04-13 09:25:47
2024-04-13 09:23:30
2024-04-13 09:23:03
2024-04-13 09:22:28
2024-04-13 09:21:10
2024-04-13 09:19:53
2024-04-13 09:17:15

ts log

video-list-layout.component.ts:58 vodTime: 2024-04-13 09:35:41, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:34:02, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:26:40, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:23:03, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:25:47, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:35:15, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:17:15, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:26:14, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:19:53, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:23:30, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:21:10, isFavorite: false
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:22:28, isFavorite: false

If I remove 'isFavorite' in GraphQL, its order will become correct.

    searchVideo(searchParams: $searchParams){
      id
      uniqueName
      vodName
      vodYear
      typeName
      vodArea
      vodPics
      vodRemarks
      vodDoubanScore
      vodDoubanId
      vodTime
      lastEpisode
      resources
#      isFavorite
    }

java log:

2024-04-13 09:40:37
2024-04-13 09:39:56
2024-04-13 09:39:30
2024-04-13 09:38:56
2024-04-13 09:37:52
2024-04-13 09:37:32
2024-04-13 09:35:41
2024-04-13 09:35:15
2024-04-13 09:34:02

ts log

video-list-layout.component.ts:58 vodTime: 2024-04-13 09:40:37, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:39:56, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:39:30, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:38:56, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:37:52, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:37:32, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:35:41, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:35:15, isFavorite: undefined
video-list-layout.component.ts:58 vodTime: 2024-04-13 09:34:02, isFavorite: undefined
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Apr 13, 2024
@bclozel
Copy link
Member

bclozel commented Apr 13, 2024

I don't think this is strictly related to Spring for GraphQL. I think that what happens here is that the "favorite" property is fetched asynchronously and this means that videos are completely resolved by the GraphQL engine when all properties are resolved, in this case "out of order".

I'm not sure if anything can be done at the Spring level to work around that.

@rstoyanchev
Copy link
Contributor

There might be something less obvious going on. I would be surprised if async execution impacts the order. I imagine the AsyncExecutionStrategy prepares a list of futures, and fills out the results, keeping the same order, but I could be wrong.

A couple of suggestions for further investigation.

  1. Check if this due to server side processing vs client side deserialization. You can use a WebGraphQlInterceptor to check the ExecutionResult on the server side. Or write a server-side test, e.g. a slice test or a test that uses ExecutionGraphQlServiceTester.

  2. Verify if this is GraphQL Java behavior independent of Spring. To do that, comment out the controller methods and use a RuntimeWiringConfigurer bean to register DataFetchers directly with GraphQL Java:

@Bean
public RuntimeWiringConfigurer runtimeWiringConfigurer() {
	return wiringBuilder -> {
		wiringBuilder.type("Query", builder -> builder.dataFetcher("searchVideo", env -> ""));
		wiringBuilder.type("Video", builder -> builder.dataFetcher("isFavorite", env -> ""));
		// ...
	};
}

If you provide an isolated sample, we can also have a look.

@rstoyanchev rstoyanchev added the status: waiting-for-feedback We need additional information before we can continue label Apr 18, 2024
@madwind
Copy link
Author

madwind commented Apr 18, 2024

https://github.com/madwind/async-graphql-test

I use GraphiQL to test
http://127.0.0.1:8080/graphiql

subscription MySubscription {
  searchVideo {
    id
    name
    isFavorite
  }
}
@Controller
public class GraphqlController {
    long interval = 100;
    long multiple = 8;
    long firstId = 5;

    @SubscriptionMapping
    public Flux<Video> searchVideo() {
        return Flux.interval(Duration.ofMillis(interval)).map(s -> new Video(s.intValue() + 1))
                .take(9)
                .doOnNext(video -> System.out.println("searchVideo: " + video.id));
    }

    @SchemaMapping
    public String name(Video video) {
        return String.valueOf((char) (video.id + 64));
    }

    @SchemaMapping
    public Mono<Boolean> isFavorite(Video video) {
        long delay = video.id == firstId ? 0 : (interval * multiple) - (interval * multiple / 10) * video.id;
        return Mono.delay(Duration.ofMillis(delay))
                .then(Mono.just(Boolean.TRUE))
                .doOnNext(s -> System.out.println("SchemaMapping: " + video.id + " delay: " + delay));
    }
}

when 'multiple' increases to 8,sometimes will get

searchVideo: 1
searchVideo: 2
searchVideo: 3
searchVideo: 4
searchVideo: 5
SchemaMapping: 5 delay: 0
searchVideo: 6
searchVideo: 7
searchVideo: 8
SchemaMapping: 1 delay: 720
SchemaMapping: 3 delay: 560
SchemaMapping: 2 delay: 640
searchVideo: 9
SchemaMapping: 4 delay: 480
SchemaMapping: 6 delay: 320
SchemaMapping: 7 delay: 240
SchemaMapping: 8 delay: 160
SchemaMapping: 9 delay: 80

websocket message

{"type":"connection_init","payload":{}} | 39 | 07:11:57.383
{"id":null,"type":"connection_ack","payload":{}} | 48 | 07:11:57.383
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"subscribe","payload":{"query":"subscription MySubscription {\n searchVideo {\n id\n name\n isFavorite\n }\n}","operationName":"MySubscription"}} | 208 | 07:11:57.383
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"5","name":"E","isFavorite":true}}}} | 134 | 07:11:57.892
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"1","name":"A","isFavorite":true}}}} | 134 | 07:11:58.223
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"3","name":"C","isFavorite":true}}}} | 134 | 07:11:58.255
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"2","name":"B","isFavorite":true}}}} | 134 | 07:11:58.257
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"4","name":"D","isFavorite":true}}}} | 134 | 07:11:58.287
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"6","name":"F","isFavorite":true}}}} | 134 | 07:11:58.333
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"7","name":"G","isFavorite":true}}}} | 134 | 07:11:58.348
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"8","name":"H","isFavorite":true}}}} | 134 | 07:11:58.365
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"next","payload":{"data":{"searchVideo":{"id":"9","name":"I","isFavorite":true}}}} | 134 | 07:11:58.380
{"id":"d6425dce-592e-4e33-ac52-603b1b534e0b","type":"complete","payload":{}} | 76 | 07:11:58.383

when 'multiple' increases to more than 8, It is missing some data.

searchVideo: 1
searchVideo: 2
searchVideo: 3
searchVideo: 4
searchVideo: 5
SchemaMapping: 5 delay: 0
searchVideo: 6
searchVideo: 7
searchVideo: 8
searchVideo: 9
SchemaMapping: 3 delay: 700
SchemaMapping: 4 delay: 600
SchemaMapping: 9 delay: 100
SchemaMapping: 8 delay: 200
SchemaMapping: 1 delay: 900
SchemaMapping: 7 delay: 300
SchemaMapping: 2 delay: 800
SchemaMapping: 6 delay: 400

websocket message

{"type":"connection_init","payload":{}} | 39 | 07:15:59.685
{"id":null,"type":"connection_ack","payload":{}} | 48 | 07:15:59.703
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"subscribe","payload":{"query":"subscription MySubscription {\n searchVideo {\n id\n name\n isFavorite\n }\n}","operationName":"MySubscription"}} | 208 | 07:15:59.703
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"next","payload":{"data":{"searchVideo":{"id":"5","name":"E","isFavorite":true}}}} | 134 | 07:16:00.247
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"next","payload":{"data":{"searchVideo":{"id":"8","name":"H","isFavorite":true}}}} | 134 | 07:16:00.756
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"next","payload":{"data":{"searchVideo":{"id":"7","name":"G","isFavorite":true}}}} | 134 | 07:16:00.759
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"next","payload":{"data":{"searchVideo":{"id":"6","name":"F","isFavorite":true}}}} | 134 | 07:16:00.771
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"next","payload":{"data":{"searchVideo":{"id":"2","name":"B","isFavorite":true}}}} | 134 | 07:16:00.774
{"id":"342dc0a6-04e7-4171-874f-5a74399d301b","type":"complete","payload":{}} | 76 | 07:16:00.776

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Apr 18, 2024
@bclozel
Copy link
Member

bclozel commented Apr 19, 2024

I am reproducing the same behavior when commenting out the @Controller annotation and replacing the Spring for GraphQL setup with a plain GraphQL Java setup:

package com.example.asyncgraphqltest;

import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.graphql.execution.RuntimeWiringConfigurer;

@Configuration
public class GraphQlConfiguration {

	@Bean
	public RuntimeWiringConfigurer runtimeWiringConfigurer() {
		GraphqlController controller = new GraphqlController();
		return wiringBuilder -> {
			wiringBuilder.type("Subscription", builder -> builder.dataFetcher("searchVideo", env -> controller.searchVideo()));
			wiringBuilder.type("Video", builder -> builder.dataFetcher("isFavorite", env -> controller.isFavorite(env.getSource()).toFuture()));
			wiringBuilder.type("Video", builder -> builder.dataFetcher("name", env -> controller.name(env.getSource())));
		};
	}
}

Using the following query:

subscription MySubscription {
  searchVideo {
    id
    name
    isFavorite
  }
}

@bbakerman
Copy link

Nominally graphql-java keeps fields in order. Its async but its waits for all futures the complete and then keeps them in a LinkedHashMap in query field order

query q {
   searchVideo {
    a
    b
    c
  }
}

will produce a result like

{
   data :{
      searchVideo :  [ {
        a : "..."
        b : "..."        
        c : "..."
     }
  }
}

However this is a Subscription and it acts differently in many ways.

The original issue was reported here at graphql-java/graphql-java#3563 and it never mentioned subscriptions and we missed the SubscritionsMapping

I don't know off hand what is happening here but Subscriptions do run differently.

The first field is expected to produce a Publisher of events objects. The engine then subscribes to that Publisher and applies the "field subselection" over objects that are presented via that Publisher

See graphql.execution.SubscriptionExecutionStrategy#executeSubscriptionEvent for the code that runs over every published object.

Its ends up calling back to graphql.execution.ExecutionStrategy#completeField(graphql.execution.ExecutionContext, graphql.execution.ExecutionStrategyParameters, graphql.execution.FetchedValue) to complete each published in the context of that first subscription field.

This should then use the normal "keep everything in order" as per the sub selection but we seem to have evidence it does not in this case. I wonder why. This needs more debugging I think but at first glance it should keep results in sub selection order.

@bbakerman
Copy link

I created graphql-java/graphql-java#3574 to try to show how async fields (which can complete at different times- can still keep the field order.

I dont know whats going on here but I am not sure how Srring will compose

  @SchemaMapping
    public Mono<Boolean> isFavorite(Video video, @AuthenticationPrincipal User user) {

    @SchemaMapping
    public List<String> vodPics(Video video) {

I would assume the first is a CF (Mono.toFuture()) and graphql-java loves CFs.

@madwind
Copy link
Author

madwind commented Apr 21, 2024

I ran the test graphql-java/graphql-java#3574. The order is correct when requests come in one after another. However, it becomes incorrect when multiple requests are made at once.

@bbakerman
Copy link

bbakerman commented Apr 21, 2024

I ran the test graphql-java/graphql-java#3574. The order is correct when requests come in one after another. However, it becomes incorrect when multiple requests are made at once.

Can you outline how you ran multiple at a time? We are really trying to get into a better reproduction state. What setup did you have when you say multiple at a time ?

Ahh you did it on the other PR... thanks

@bbakerman
Copy link

I think I know what is happening here - I will answer here rather than the graphql-java PR because the audience that knows Reactor / Reactive better is here

The graphql-java subscriptions code uses a graphql.execution.reactive.CompletionStageMappingPublisher class that acts as both a Publisher and Subscriber to the underlying Publisher aka the reactor Flux of videos.

graphql.execution.reactive.CompletionStageMappingPublisher.CompletionStageSubscriber#onNext is called in order for every video found.

This is the code

        public void onNext(U u) {
            // for safety - no more data after we have called done/error - we should not get this BUT belts and braces
            if (onCompleteOrErrorRunCalled.get()) {
                return;
            }
            try {
                CompletionStage<D> completionStage = mapper.apply(u);
                offerToInFlightQ(completionStage);
                completionStage.whenComplete(whenNextFinished(completionStage));
            } catch (RuntimeException throwable) {
                handleThrowable(throwable);
            }
        }

So for ever video object published down the flux is makes a a callback to a mapper on that object CompletionStage<D> completionStage = mapper.apply(u); which is the a callback to the graphql engine to apply field subselection over that event object and turn it into a graphql sub selected object.

In this case the isFavourite" child field is async and hence might not have been completed at the time of onNext` being called. It was mapped in order but it might complete later.

The downstream onNext is called when that CF completes

 private BiConsumer<D, Throwable> whenNextFinished(CompletionStage<D> completionStage) {
            return (d, throwable) -> {
                try {
                    if (throwable != null) {
                        handleThrowable(throwable);
                    } else {
                        downstreamSubscriber.onNext(d); // the CF has completed - run onNext() on the downstream 
                    }
                } finally {
                    Runnable runOnCompleteOrErrorRun = onCompleteOrErrorRun.get();
                    boolean empty = removeFromInFlightQAndCheckIfEmpty(completionStage);
                    if (empty && runOnCompleteOrErrorRun != null) {
                        onCompleteOrErrorRun.set(null);
                        runOnCompleteOrErrorRun.run();
                    }
                }
            };
        }

Now the thing I dont know is what the Reactor / Reactive contract should be here.

We have a series of values n that end up being graphql mapped to CF(n) and they can complete at different times

eg 1 -> CF(1) , 2 -> CF(2), 3 -> CF(3) and it might complete in CF(1), CF(3), CF(2) order

I suspect we probably want to keep them in original emission order in a graphql sense. We do when we have a List<CF<Object>> list field. We wait for all CFS to complete before returning a list.

BUT reactive is different - we dont know when the next onNext is being called and all of a sudden we need to buffer results to keep them in order and in theory one that completes first has to wait for one before it.

If we buffer in graphql-java, we need to decide on the size of the buffer and it probably should come from user code, not the library.

@madwind
Copy link
Author

madwind commented Apr 22, 2024

Is it possible to provide a method to make the onNext invocation synchronous in user code, similar to Reactor's concatMap?

        @Override
        public void onNext(U u) {
            // for safety - no more data after we have called done/error - we should not get this BUT belts and braces
            if (onCompleteOrErrorRunCalled.get()) {
                return;
            }
            try {
//                CompletionStage<D> completionStage = mapper.apply(u);
//                offerToInFlightQ(completionStage);
//                completionStage.whenComplete(whenNextFinished(completionStage));
                downstreamSubscriber.onNext(mapper.apply(u).toCompletableFuture().join());
            } catch (RuntimeException throwable) {
                handleThrowable(throwable);
            }
        }

@bclozel
Copy link
Member

bclozel commented Apr 22, 2024

@bbakerman thanks for your analysis. In my opinion, the current behavior makes sense after all.

Queries/mutations return bounded collections in the response. The API can provide a way for clients to sort entries and paginate for large collections. In the case of subscriptions, the intent is more about getting state updates on large entities, or unbounded stream of events (pub/sub style). With these use cases, I think the GraphQL engine should indeed push events as soon as they are fully available. In my opinion, applications expecting any other sorting/ordering should instead use queries with pagination.

As you have pointed out, implementing this behavior in graphql-java would require limited buffering (which would still show that behavior when the buffering limit is reached); this would also artificially delay available data and then send large bursts of events. Introducing such behavior would probably "break" existing applications.

Let's hear from @rstoyanchev first, but my vote goes to closing this issue here and not considering it on the graphql-java side.

@bbakerman
Copy link

bbakerman commented Apr 23, 2024

downstreamSubscriber.onNext(mapper.apply(u).toCompletableFuture().join());

we can't do this - this would block the upstream Publisher until the object completes. Blocking in reactive architectures is very bad - it ties up resources that could be used for other requests.

@rstoyanchev
Copy link
Contributor

Indeed, a subscriber must not block the Publisher which may be operating on a small/fixed number of threads with the assumption of no blocking. This is also specified in the Reactive Streams spec.

Pagination and streaming are not always interchangeable, and preserving the order of publication may be important. However, as it has a cost associated, it should be possible to opt in/out

@bbakerman
Copy link

https://github.com/graphql-java/graphql-java/pull/3574/files is a PR that improves the current mechanism (cancelling inflight futures so that underlying Mono would be cancelled etc... and also provide a new way to respect the original ordering of emitted events from the source Publisher

The default mode is still "emit events as the graphql subselection completes not as they originally arrived" but there is a new mode that can be hinted at that causes the subscription code to preserve the original ordering of the source Publisher

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged
Projects
None yet
Development

No branches or pull requests

5 participants