[v3.4] Unexpected Console Warning: "Missing cache result fields"

[dylanwulf]

Intended outcome:
Should not print warning to console when two separate queries request different subsets of the same field

Actual outcome:
Console warning is printed

How to reproduce the issue:
https://github.com/dylanwulf/react-apollo-error-template/tree/cache-miss-error (use branch cache-miss-error)
Instructions: Start app, open console, click any unselected radio button, see that a warning is printed to console.

Conditions necessary for issue to occur:

• Two separate queries request different subsets of the same field
• Both queries have the same variable values
• One query resolves before the other
• Both queries are using notifyOnNetworkStatusChange: true
• Both queries are using fetchPolicy: 'cache-and-network'
• Apollo Client version must be >= 3.4.0-beta.14 (possibly caused by Preserve no-cache fetchPolicy with notifyOnNetworkStatusChange #7761?)

Versions

  System:
    OS: Windows 10 10.0.19042
  Binaries:
    Node: 14.16.1 - C:\Program Files\nodejs\node.EXE
    Yarn: 1.21.1 - C:\Program Files (x86)\Yarn\bin\yarn.CMD
    npm: 6.14.12 - C:\Program Files\nodejs\npm.CMD
  Browsers:
    Chrome: 91.0.4472.114
    Edge: Spartan (44.19041.1023.0), Chromium (91.0.864.59)
  npmPackages:
    @apollo/client: 3.4.0-rc.15 => 3.4.0-rc.15

[benjamn]

Thanks for flagging this change in behavior @dylanwulf!

This appears to be a consequence of this change from #7761, specifically the addition of the || shouldNotify case to the cache-and-network fetch policy logic:

apollo-client/src/core/QueryManager.ts

Lines 1420 to 1427 in edab367

	case "cache-and-network": {
	const diff = readCache();
	if (diff.complete || returnPartialData || shouldNotify) {
	return [
	resultsFromCache(diff),
	resultsFromLink(),
	];

Since your reproduction is explicitly requesting notifyOnNetworkStatusChange: true, I think the extra notification makes sense. The warnings about missing fields come from delivering incomplete results from the cache. Those warnings can be noisy, but I believe they are harmless in this case, especially since the cache-and-network policy consults the network regardless.

[dylanwulf]

@benjamn ah ok I see. In that case, why doesn't the warning show up when I use cache-first fetch policy? Seems like the same reasoning should apply there

[dylanwulf]

Ok, I guess this issue being closed means that it's expected for this console warning to happen with cache-and-network but not with cache-first?

[benjamn]

@dylanwulf My hunch is that cache-and-network triggers more (unconditional) network requests, which are ultimately responsible for writing non-overlapping data into the cache using different queries, which produces the missing field warnings. The cache-first fetch policy makes fewer network requests, and so doesn't end up triggering this behavior.

[benjamn]

As for the preemptive closing of the issue (sorry!), we're doing some general cleanup before the v3.4 release, and we think these warnings are expected/harmless, though you're right that they are new in v3.4. We can continue to iterate on warning noise after v3.4 is released, unless you think there's a deeper problem hiding here?

[dylanwulf]

@benjamn ok I understand thank you! It just seemed strange to me that it was triggering for cache-and-network but not cache-first even though the data wasn't in the cache in either scenario. But if that's intentional then I have no further questions/issues here 🙂

[sebastienbarre]

@dylanwulf @benjamn

I'm experiencing these as well since I switched to rc15/18. I'm getting a lot of them, systematically.

However they are triggered by the exact same request in my case, requesting the exact same fields. Only the variable changes. Can I humbly request a flag to lower the verbosity? With the associated stack trace, these are taking over my browser console output.

Below are 3 such requests, which were performed in a row. Apologies, I don't know how to format the request payload seen in the Chrome's network tab, I'll be copy/pasting.

{"operationName":"myTimeCard","variables":{"startDate":"2021-07-05","endDate":"2021-07-11"},"query":"query myTimeCard($startDate: Date!, $endDate: Date!) {\n  me {\n    id\n    timeEntries(\n      filters: {date: {between: [$startDate, $endDate]}}\n      pagination: {first: 100}\n    ) {\n      totalCount\n      pageInfo {\n        ...pageInfoFields\n        __typename\n      }\n      edges {\n        cursor\n        node {\n          ...timeEntryFields\n          __typename\n        }\n        __typename\n      }\n      __typename\n    }\n    __typename\n  }\n}\n\nfragment pageInfoFields on PaginationPageInfo {\n  hasPreviousPage\n  hasNextPage\n  startCursor\n  endCursor\n  __typename\n}\n\nfragment timeEntryFields on TimeEntry {\n  id\n  date\n  hours\n  description\n  project {\n    id\n    name\n    jobType\n    __typename\n  }\n  proposal {\n    id\n    name\n    __typename\n  }\n  submitted\n  employeeManagerApproved\n  projectManagerApproved\n  __typename\n}\n"}

{"operationName":"myTimeCard","variables":{"startDate":"2021-06-28","endDate":"2021-07-04"},"query":"query myTimeCard($startDate: Date!, $endDate: Date!) {\n  me {\n    id\n    timeEntries(\n      filters: {date: {between: [$startDate, $endDate]}}\n      pagination: {first: 100}\n    ) {\n      totalCount\n      pageInfo {\n        ...pageInfoFields\n        __typename\n      }\n      edges {\n        cursor\n        node {\n          ...timeEntryFields\n          __typename\n        }\n        __typename\n      }\n      __typename\n    }\n    __typename\n  }\n}\n\nfragment pageInfoFields on PaginationPageInfo {\n  hasPreviousPage\n  hasNextPage\n  startCursor\n  endCursor\n  __typename\n}\n\nfragment timeEntryFields on TimeEntry {\n  id\n  date\n  hours\n  description\n  project {\n    id\n    name\n    jobType\n    __typename\n  }\n  proposal {\n    id\n    name\n    __typename\n  }\n  submitted\n  employeeManagerApproved\n  projectManagerApproved\n  __typename\n}\n"}

{"operationName":"myTimeCard","variables":{"startDate":"2021-06-21","endDate":"2021-06-27"},"query":"query myTimeCard($startDate: Date!, $endDate: Date!) {\n  me {\n    id\n    timeEntries(\n      filters: {date: {between: [$startDate, $endDate]}}\n      pagination: {first: 100}\n    ) {\n      totalCount\n      pageInfo {\n        ...pageInfoFields\n        __typename\n      }\n      edges {\n        cursor\n        node {\n          ...timeEntryFields\n          __typename\n        }\n        __typename\n      }\n      __typename\n    }\n    __typename\n  }\n}\n\nfragment pageInfoFields on PaginationPageInfo {\n  hasPreviousPage\n  hasNextPage\n  startCursor\n  endCursor\n  __typename\n}\n\nfragment timeEntryFields on TimeEntry {\n  id\n  date\n  hours\n  description\n  project {\n    id\n    name\n    jobType\n    __typename\n  }\n  proposal {\n    id\n    name\n    __typename\n  }\n  submitted\n  employeeManagerApproved\n  projectManagerApproved\n  __typename\n}\n"}

The only part that changes here are the variables:
"startDate":"2021-07-05","endDate":"2021-07-11", "startDate":"2021-06-28","endDate":"2021-07-04", "startDate":"2021-06-21","endDate":"2021-06-27" -- as you can surmise, I'm looking at a weekly calendar UI, going back in time week by week.

Each time I press the "Previous week" button, a request for that week's date interval is made, and each time I'm getting:

"Missing cache result fields: me.timeEntries 
[Error: Can't find field 'timeEntries' on Employee:12 object
    at new MissingFieldError (http://lo…]
0: Error: Can't find field 'timeEntries' on Employee:12 object at new MissingFieldError (http://localhost:8080/_snowpack
...

Note: the me field's __typename is Employee, and the authenticated employee's id in these examples is 12.

The thing is, the me entrypoint field is used extensively. This is how our users receive their data.
If they look at their time entries page, we will request:

me { 
 id   
 timeEntries {
  ...
  }
}

then if they head to their projects page, we will request:

me { 
 id   
 projects {
  ...
  }
}

in their proposals page:

me { 
 id   
 proposals {
  ...
  }
}

etc. The schema itself has many other "root" fields than me but you get the idea, and I assume there is nothing out of the ordinary here in our schema (?). There is an actual employee root field as well that accepts an id, and me is essentially just a convenience shortcut that returns the same type, Employee, but for the authenticated employee.

Before performing these 3 requests in this specific example, one was made as soon as they authenticated, to get their name and profile picture, so I assume this filled the cache with the corresponding data first:

me {
  name
  profilePictureUrl
}

Am I possibly missing something with these new warnings/eerroors? This type of request on the me field in our app will never fully features all the fields it can accept, that would be way too much data to fetch. My assumption is that 3.4 would merge these just fine, as it had been working well in 3.3 (to my knowleddge). I can see the data being cached fine in 3.3. For example, if I head back in the UI to a week that was fetched before, the data comes from the cache instantaneously and the UI refreshes right away, which is very appreciated.

Thanks

[benjamn]

@sebastienbarre Thanks for the examples. I don't think you're doing anything wrong here. The warnings are just too noisy.

The original goal of these warnings was to provide clues about why an unexpected network request happened, but in your case the network request seems to be very much expected/normal, so the warning is not helpful.

As you might guess from the PR linked above, the current plan is to demote these invariant.warn messages to invariant.debug, whose output is hidden by default, unless you deliberately call setLogVerbosity("debug") in your application.

[sebastienbarre]

@benjamn thanks for the quick solution, appreciated. I'll test it out when ready.

[benjamn]

@sebastienbarre Alright, these warnings should be hidden by default in @apollo/client@3.4.0-rc.19 (just published).

[sebastienbarre]

@benjamn this did the trick, many thanks

[hwillson]

This should be resolved in @apollo/client@latest - let us know if not.