Streaming responses (@defer) waits on the server instead of incrementally delivering responses

[jer-k]

The overview is that

      for await (const chunk of httpGraphQLResponse.body.asyncIterator) {
        body.push(chunk);
      }

this await is stopping the server from incrementally delivering the responses and instead they're all delivered at once.

Messages from the Discord question

https://discord.com/channels/1022972389463687228/1261337794501152880/1261337794501152880

I have a demo application using Next.js where I am doing all sorts of learning https://github.com/jer-k/graphql-rsc-dashboard and I've set up Apollo Server to work with the @defer directive. What I'm noticing is that my component isn't rendering right away and the deferred data seems to be sent to the browser at the same time as the initial data.

This component ClientBookStores (https://github.com/jer-k/graphql-rsc-dashboard/blob/main/components/client-book-stores.tsx) has the query with the @defer directive. There is also logging added so that I can see when the data is arriving in the browser.

The resolvers are located at
book - https://github.com/jer-k/graphql-rsc-dashboard/blob/main/graphql/resolvers.ts#L4-L10 This has a 200ms delay to simulate say a database call
stores - https://github.com/jer-k/graphql-rsc-dashboard/blob/main/graphql/resolvers.ts#L40-L43 This has a 2 second delay to simulate data far away and to be deferred.

When I load the page, the logs look like this.

what is data? undefined true 7:46:22
what is data? undefined true 7:46:22
what is data? {book: {…}} false 7:46:25
what is data? {book: {…}} false 7:46:25

The third log, the first data returned, looks like this

book: 
author: 
  name: "Hofstadter, Douglas R."
  __typename: "Author"
dateAdded: "2024-05-05 03:08:03"
id: "2015"
isbn: "9780465026562"
title: "GODEL ESCHER BACH : ETERNAL GOLDEN BRAID / 20TH ANNIVERSARY ED"
__typename: "Book"

which has the correct initial data without the deferred stores.

The fourth log has everything above as well as

stores: Array(2)
0: {__typename: 'Store', name: 'First Store', address: '123 Main Street'}
1: {__typename: 'Store', name: 'Second Store', address: '567 1st Ave'}

So all the data is being properly returned. However when we look at the timestamps, both the third and fourth logs are next to each other, instead of two second apart. Am I doing something wrong in the resolvers to correctly simulate and use @defer?

I added some more logging to the resolvers and now I have

Request started! ... 8:0:27

inside the short delayed book resolver, before await. Will wait 1 second 8:0:27

inside the stores resolver, before await. Will wait 2 seconds 8:0:28

And then in the browser / client side

what is data? {book: {…}} false 8:0:30
what is data? {book: {…}} false 8:0:30

I compared this to my work project that uses Ruby on Rails for the backend. The logs there look like

On the server

inside of environment. Top level. Adding 1 second sleep 2024-07-17 08:15:10 

inside of environment - pods. @deferred object 2024-07-17 08:15:12

On the browser / client

what is data? {app: {}} false 8:15:12
what is data? {app: {}} false 8:15:13

So i can see that a response is being returned to client around the same time the deferred field is starting to be queried