[v4] Both result data and exception are sometimes null on network result

Zony-Zhao commented 4 years ago

Describe the bug Just upgraded to graphql_flutter: ^4.0.0-beta.3. What I did is a normal query as I did before.

I'm not sure what is the problem.

query {
  userByToken {
    newOrders(query: {skip: 0, sortBy: "createdAt", order: 1}) {
      id
      dishMetas {
        dish {
          id
          name
          store {
            id
            name
            description
            avatar
            district {
              name
            }
          }
          tag
          price
          avatar
        }
        quantity
        remark
      }
      status
      initiator {
        id
        name
        tel
        address
      }
      deliverPrice
      createdAt
    }
  }
}

I do the same query in postman which is all fine. I wonder in what situation this data would be null? isLoading is false, and there is no exception. Having worked on it for hours and have no clue.

Zony-Zhao commented 4 years ago

I'm not sure using variable in resolved field is permitted or not, and encouraged or not. But when I change the endpoint to use variable at start. Everything goes well.

Zony-Zhao commented 4 years ago

post it on github. and let more people see it. I'll anwser you there.

------------------ Original message ------------------ From: "Jakub Myśliwiec"; Sendtime: Tuesday, Oct 20, 2020 5:19 PM To: "zino-app/graphql-flutter"; Cc: "zonyzhao"1668069501@qq.com; "State change"; Subject: Re: [zino-app/graphql-flutter] result.data is null. (#747)

I have the same issue, can you explain more precisely how you managed to solve it? I don't get what endpoint you changed.

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub, or unsubscribe.

jmysliv commented 4 years ago

I had similar issue to yours, the query result data and exception was null, but query worked fine in graphql playground. The difference was that some queries that was written earlier worked fine in my flutter app, only the new queries I added had that issue. I deleted comment, because problem "magically" disappear, after I restarted app few times, without any change in code. When I find out what was causing the problem I'll post it here.

Zony-Zhao commented 4 years ago

I'm not that lucky as you. I restarted IDE and invalidate cache. Even restart the PC. didn't work. I solved it by change mygraphql query and backend resolver. As far as I guess, I think maybe something with network or cache.

micimize commented 4 years ago

Sorry to hear you beat your head on the wall here for so long – it is likely this is due to #744. Can you add:

your client, cache, and link declarations
the QueryOptions / if you using the gql helper function from graphql_flutter
the returned data from postman

Also try with FetchPolicy.noCache to see if you get the same data as postman.

Basically, what I think is probably happening here is that the returned structure is somehow slightly unexpected, so the write/read loop on the response data results in null due to invalid structure.

micimize commented 4 years ago

Details I added in the discord:

...There is likely some mismatch between the requested document structure and result, but it is unexpected behavior. The following should always pass:
assert(
!(result.data == null && result.exception == null && result.source == QueryResultSource.network),
'network results should always have either data or an exception, but $result has neither. '
'This may be caused by a malformed response or cache misconfiguration.'
);
...Should have time to solve this later this week.

jmysliv commented 4 years ago

@micimize Here's my client cache and link declaration:

String typenameDataIdFromObject(Object object) {
  if (object is Map<String, Object> &&
      object.containsKey('__typename') &&
      object.containsKey('id'))
    return "${object['__typename']}/${object['id']}";
  return null;
}

  final url = DotEnv().env["GRAPHQL_URL"];
  final HttpLink httpLink = HttpLink(url);

  final AuthLink authLink = AuthLink(getToken: () async {
    final token = await TokenService.getToken();
    return '$token';
  });

  final Link link = authLink.concat(httpLink);

  ValueNotifier<GraphQLClient> client = ValueNotifier(GraphQLClient(
    cache: GraphQLCache(
      dataIdFromObject: typenameDataIdFromObject,
    ),
    link: link,
  ));

  GraphqlClientService(client: client);

here's my query and QueryOptions:

final friendsList = gql(r'''
 query FriendsList {
  me {
    friends {
      __typename
      id
      name
      email
      age
      favoriteAlcoholName
      favoriteAlcoholType
      description
      gender
      genderPreference
      alcoholPreference
      agePreferenceFrom
      agePreferenceTo
      latestLocation {
        latitude
        longitude
      }
    }

  }
}
''');

  final WatchQueryOptions options = WatchQueryOptions(
        document: query.friendsList,
        fetchResults: true,
        fetchPolicy:
            fetchCache ? FetchPolicy.cacheFirst : FetchPolicy.networkOnly); //fetchCache is set to false

    final queryResult = await client.value.query(options);
    checkQueryResultForErrors(queryResult); //checks if queryResult has exceptions if it has, our custom exception is thrown
    print(queryResult.data);
    print(queryResult.exception);
    print(queryResult.source);

I'm pretty sure that my backend works fine because when I run the same query in graphql playground it works fine and I get the following json as a result:

{
  "data": {
    "me": {
      "friends": []
    }
  }
}

However when I run my flutter app that query works randomly, sometimes it fetches result properly, but more often both the result data and exceptions is null and source is network. Sometimes restarting app helps but not always.

micimize commented 4 years ago

@jmysliv thanks for the info – the fact that it's inconsistent is even more troubling than it just not working. Does it ever have friends data? Also, try this in the playground and see if __typenames are added in the result:

query FriendsList {
  __typename
  me {
    __typename
    friends {
      __typename
      id
      name
    }
  }
}

jmysliv commented 4 years ago

@micimize thanks for reply. Yes, but I was testing without any friends added. Here's result for your query when I added friend in the database.

{
  "data": {
    "__typename": "Query",
    "me": {
      "__typename": "Account",
      "friends": [
        {
          "__typename": "Account",
          "id": "6512afe0-c173-4d66-b803-57891fb3172e",
          "name": "kuba"
        }
      ]
    }
  }
}

jmysliv commented 4 years ago

Okay, I think I found source of the problem. I tried your query inside my flutter app and it started working. The same result I achieved when I commented code inside this function (it returns null all the time).

String typenameDataIdFromObject(Object object) {
  // if (object is Map<String, Object> &&
  //     object.containsKey('__typename') &&
  //     object.containsKey('id'))
  //   return "${object['__typename']}/${object['id']}";
  return null;
}

I think there is some problem with cache when there isn't __typename field in the query result. However it's quite weird cause I'm checking in this function if object contains __typename field and return null when it doesn't. What's more problem occurs even when my FetchPolicy is set to NetworkOnly, so cache shouldn't be used at all in that case but it seems that it is used. Adding __typename on every level of nested query solves the problem, but I still think that something is not working like it should. Still, thanks for help!

Zony-Zhao commented 4 years ago

While @jmysliv is using the stable version, I 'm using And my client

micimize commented 4 years ago

@Zony-Zhao and @jmysliv I made a PR that should hopefully provide more info on what's going on here – try running your queries with the following to see if it gives more fruitful errors:

dependency_overrides:
  graphql:
    git: 
      url: git@github.com:micimize/graphql-flutter.git
      ref: norm_data_handling
      path: packages/graphql
  normalize:
    git: 
      url: git@github.com:micimize/ferry.git
      ref: partial_paths
      path: normalize

jmysliv commented 4 years ago

@micimize Seems that nothing changed cause I get the following query result after I run my previous code with the dependency override:

QueryResult(source: QueryResultSource.network, data: null, exception: null, timestamp: 2020-10-26 22:04:16.678639)

However as I write before, when I added __typename field to my query it started work fine so I don't get any errors now.

SanjiKir commented 4 years ago

@micimize I probably will join this issue because I was trying to hunt the bug in my app as well, I thought there is some issue with rebroadcasting, but apparently, I have the same problem as 2 guys above. To shortly describe in mutation on update I am writing newly created data to cache, however sometimes, absolutely randomly they are not written. I was trying to replicate this bug for months now and I've just seen this issue. The worst thing is that our customers sometimes complain about it as well :( Hopefully, that will be fixed soon!

SanjiKir commented 4 years ago

Okay, small update. I've made a condition in update function if (result.data == null) { return; } and I've made a breakpoint there. Then I managed to replicate the bug, however, the breakpoint didn't work (meaning data was not null). I've also inspected the cache and I don't see a newly created item in there, possibly the problem lies in cache.writeQuery. I hope this helps somehow.

micimize commented 4 years ago

@SanjiKir if you reproduce again with these overrides, does writeQuery throw an error? Either way, what is the query + data that sometimes throws and sometimes doesn't? We need to establish a failing test case, and figure out if it's due to an unexpected data structure or a race condition or what.

dependency_overrides:
  graphql:
    git: 
      url: git@github.com:micimize/graphql-flutter.git
      ref: norm_data_handling
      path: packages/graphql
  normalize:
    git: 
      url: git@github.com:micimize/ferry.git
      ref: partial_paths
      path: normalize

micimize commented 4 years ago

I'm really perplexed by this issue, and can't seem to find a solid test case / hypothesis for when this happens, but given the current behavior description of "sometimes writeQuery/readQuery fails it could be multiple issues.

Anyone running in to this please test with a clean cache and the above overrides, and record a sequence of cache that can create the write/read round-trip failure. It is possible that someone might be running in to https://github.com/gql-dart/ferry/issues/98, or that #754 solves the issue in some cases but not all, but we need data that can be turned into an actual test case.

SanjiKir commented 4 years ago

@micimize I will give it a shot, today or tomorrow. Pinky swear :D Just to clarify things, in case this thing occurs again instead of silently failing it should throw an error, right?

micimize commented 4 years ago

@SanjiKir yes – in fact you prompted me to add the following in the event of non-structural roundtrip cache failures:

If write succeeds but readQuery then returns null, a CacheMissException will be added and the data will not be overwritten

micimize commented 3 years ago

merged #754, but I am not confident it solves whatever is happening here. Regardless, please add partialDataPolicy: PartialDataCachePolicy.reject to your cache options when using the latest there.

micimize commented 3 years ago

@Zony-Zhao this looks like an entirely different possible issue. Either the client is not adding the error to the exception for some reason, or you aren't checking for result.hasException before attempting to access result.data['userByToken']. In this particular case, result.data == null should be true

Zony-Zhao commented 3 years ago

Yeah,My bad. This is another thing. I'll delete the post in case of misdirecting others.

SanjiKir commented 3 years ago

@micimize Extremely sorry for breaking my pinky swear, but I just managed to test it. So I bumped to v4.beta.5 added

partialDataPolicy: PartialDataCachePolicy.reject

And duplicated the bug. The update was no written to the cache, yet I didn't see any error.

Also I am not 100% sure, but I believe this problem was in v3 as well when I was using old options to write to the cache.

SanjiKir commented 3 years ago

@micimize Okay update.

I debugged it from all ends. What I've noticed, is that update method randomly returns the wrong result from the server. To be more specific I am creating an entity called order. In update I expect the result from the server and I want to write it to the cache, so it will be rebroadcasted and showed immediately. However update method of CreateOrderMutation returns an absolutely different order. Well, I was like, **** we screwed up on the back-end. But, no! I debugged it locally on the BE and in the Flutter app, BE returns the correct result from the endpoint, however, update method ends up with absolutely wrong result.

Do you have any ideas what can be wrong?

micimize commented 3 years ago

@SanjiKir

do you mean that in update, when result.source is network, result.data of the QueryResult passed to Mutation.update contains the data for the previous CreateOrderMutation?
what are some concrete examples of the operation, variables, and result data here?
is there anything else happening in the app at the same time, like are multiple CreateOrderMutations happening at once?

Actual code excepts are invaluable here. Maybe:

there's a race condition
or update is somehow getting a stale result in place of an optimistic one before the network response has been received
or the writeQuery -> readQuery roundtrip is overwriting all the data with optimistic results from elsewhere because of some normalization issue __typename / id are the same between two instances of the same mutation

FickleLife commented 3 years ago

I just stumbled across this error, adding some more info here which might help diagnose. My query is:

query BarcodeScanLog($limit: Int = 50) {
  barcodeScanLog(limit: $limit) {
    __typename
    createdAt
    product {
      __typename
      id
      name
      brand {
        __typename
        name
      }
    }
  }
}

I was getting NoSuchMethodError: The method '[]' was called on null.. To resolve, I had to pass a variable for limit instead of relying on the default in the query. I'm on graphql_flutter: ^4.0.0-beta.3

micimize commented 3 years ago

@FickleLife the fact that the variable made a difference is noteworthy, but based on what you're saying it isn't necessarily the same issue:

what was the complete stacktrace?
where was the error thrown – in update?
What is the result.source & expected data? Is result.data null?
Does it fail consistently, or only after a second attempt?

SanjiKir commented 3 years ago

@SanjiKir

do you mean that in update, when result.source is network, result.data of the QueryResult passed to Mutation.update contains the data for the previous CreateOrderMutation?

Not sure about the previous one, the funny thing it's actually related to the entity the order is being placed on. So Order has always a place, right. And in update the wrong order is always from the same place. Everything else you said seems to be accurate.

what are some concrete examples of the operation, variables, and result data here?

mutation

mutation CreateOrder($placeId: ID!, $lines: [OrderLineCreate!]!, $name: String) {
  createOrder(data: {
    placeId: $placeId
    lines: $lines
    name: $name
  }){
    ...orderFields
  }
}

Fragment

fragment orderFields on Order {
    __typename
    id
    createdUtc
    updatedUtc
    orderState
    name
    orderNumber
      place {
        __typename
        id
        name
      }
      orderLines {
        __typename
        id
        price
        quantity
        unitPrice
        orderLineState
        createdUtc
        product {
          __typename
          id
          name
          priceSell
          printingDeviceId
        }
      }
}

Result data correct

 {__typename: Order, id: f2b4f257-350a-4d9e-9a02-c3c1dd4add56, createdUtc: 1605999494381, updatedUtc: 1605999494381, orderState: Opened, name: null, orderNumber: MY2020000019, place: {__typename: Place, id: 9b406059-a85f-4ffd-ae3d-89821fb73cbc, name: Bar 3}, orderLines: [{__typename: OrderLine, id: be2c59d8-3721-4adf-be70-34a4af4703ac, price: 5000, quantity: 1, unitPrice: 5000, orderLineState: Opened, createdUtc: 1605999494381, product: {__typename: Product, id: 52f23a2c-c4b5-4e27-90ba-d6b24a354a1b, name: Red label glass, priceSell: 5000, printingDeviceId: 92a33c80-5285-4c6c-88aa-2222fe6f373d}}]}

Result data wrong

{__typename: Order, id: 5e74a8c8-6724-4a07-aeb7-c0670e78e98e, createdUtc: 1605998577724, updatedUtc: 1605998625731, orderState: Closed, name: null, orderNumber: MY2020000005, place: {__typename: Place, id: 9b406059-a85f-4ffd-ae3d-89821fb73cbc, name: Bar 3}, orderLines: [{__typename: OrderLine, id: 006bce75-0154-4929-8071-86a29b2d5e6c, price: 5000, quantity: 1, unitPrice: 5000, orderLineState: Paid, createdUtc: 1605998577724, product: {__typename: Product, id: 52f23a2c-c4b5-4e27-90ba-d6b24a354a1b, name: Red label glass, priceSell: 5000, printingDeviceId: 92a33c80-5285-4c6c-88aa-2222fe6f373d}}]}

Notice that the place is the same, however order state is closed. Meaning this order was created and closed earlier and now we've tried to create a new one, however both update and onCompleted returned the old order.

is there anything else happening in the app at the same time, like are multiple CreateOrderMutations happening at once?

No, no race conditions, no multiple order creations, nothing like that.

Actual code excepts are invaluable here. Maybe:

there's a race condition

No race condition, no mutation are running

or update is somehow getting a stale result in place of an optimistic one before the network response has been received

We don't use optimistim so far

or the writeQuery -> readQuery roundtrip is overwriting all the data with optimistic results from elsewhere because of some normalization issue __typename / id are the same between two instances of the same mutation

This I am not sure I understand, if you can elaborate I can do a double check. We do not provide a custom function for normalization, which means we use the default one.

cc @micimize

micimize commented 3 years ago

@SanjiKir Thanks for the details – on the last item if you aren't using optimisticResult at all then it can't be that.

I've made a branch and added a test and data for investigating this issue, but have still not had any luck actually reproducing: https://github.com/zino-app/graphql-flutter/blob/d20d061fa2309636b1a9827dbc1b89e26605b45e/packages/graphql/test/graphql_client_test.dart#L434-L435

pub run test test/graphql_client_test.dart -n 'watchQuery mutations are isolated'

It is rather perplexing. That the cache write has to both fail silently, and then succeed to read an old value, implies either that something is critically wrong (i.e. hive somehow fails puts occasionally), or there's some wacky error, like a custom CreateOrderVariables object with a toJson() that returns the correct variables only once, then null afterwards. In other words, I still have no idea why this is happening

SanjiKir commented 3 years ago

@micimize Okay I started debugging graphql lib now to solve this problem. What I've found out that it tries to eagerly resolve it from cache (see image), because mutation have default cache and network policy. Now I am not 100% sure, but my guess is since we do not provide id for lines it resolves the latest case of this mutation using the placeId and the productId. So to reproduce it we have to:

Create an order assign place and orderlines to it.
Close the order
Create the exact same order on the same place
Now after we create graphql returns the old order which we already closed because place and OL are the same.

Now I am not sure this is actually correct behavior, it's probably done for optimism, right? Any ideas on how can I fix it besides using networkOnly?

micimize commented 3 years ago

@SanjiKir ohhhh ok, we finally have an answer to what's going on. So, actually I would recommend using networkOnly for now.

Here's what's happening: The default policy for client.watchQuery is cacheAndNetwork, but that is actually a bad default policy for mutations, which is why the default policy for client.mutate is networkOnly. However, because we use watchQuery for the Mutation widget (because we have no watchMutation), you automatically get the last result of the mutation with the same variables from the cache, which is probably what made it seem random.

This is a serious issue, but different from this one. Here're more details on exactly what's happening.

Am closing this in favor of #774

HofmannZ commented 3 years ago

:tada: This issue has been resolved in version 4.0.0 :tada:

The release is available on GitHub release

Your semantic-release bot :package::rocket:

zino-hofmann / graphql-flutter

[v4] Both result data and exception are sometimes null on network result #747