apollo-server-core v2.24 breaks Apollo Studio data reporting

[molomby]

The changes made in #4142 (released in v2.24) have broke the data reporting needed by Apollo Studio. Downgrading our app to use v2.23 of apollo-server-core, apollo-server-express and apollo-server-micro restored the correct behaviour.

I suspect only the Studio free tier is affected but haven't access to a paid account to confirm.

Expected Behaviour

Stats on operations performed against the GraphQL endpoint are sent to Apollo Studio.

Observed Behaviour

The behaviour we're seeing on 2.24 is, when the app starts up, we get an initial burst of data sent though then nothing until the next restart. The initial "burst" updates the schema (stored by Studio) and includes stats for several requests. It leave us with graphs that look like this...

Speculation

If I'm understanding the code here, when the app starts up Server waits up to initialDelayMaxMs before reporting to Studio. In addition to the data sent, this initial report also returns data to the app which is used to configure future reports. Specifically, the tracesIgnored flag informs the app whether trace data is worth sending, based on the subscription level of the Studio org. in v2.24 this flag is used to set the internal graphMightSupportTraces var. However, somewhere in the reporting code, the meaning of this var is flipped. When graphMightSupportTraces is false, only trace data is sent.

At least that's what I think is happening. It certainly explains the behaviour we're observing – we get the first batch of stats data, included in that initial request, then only trace data which is ignored by Studio when the org is on the free tier.

Reproduction

You can seemingly reproduce this with any Apollo Server app. I've used the "Getting Started" example:

# Clone a super-simple app
git clone git@github.com:molomby/apollo-studio-issue-reproduction.git

# Export your env vars to enable studio data reporting
export APOLLO_KEY=service:Debugging-data-reporting:12345fake12345fake
export APOLLO_GRAPH_VARIANT=current
export APOLLO_SCHEMA_REPORTING=true

# Start the app
# Note "libraryVersion": "apollo-server-core@2.24.0" in the output
node index.js
# Apollo usage reporting starting! See your graph at https://studio.apollographql.com/graph/Debugging-data-reporting/?variant=current
# Apollo schema reporting starting! See your graph at https://studio.apollographql.com/graph/Debugging-data-reporting/?variant=current with server info {"bootId":"68a8c0f6-f4d2-489a-af71-174ebbb0c308","graphVariant":"current","platform":"local","runtimeVersion":"node v12.22.1","executableSchemaId":"4290076ab12ba8e295d7d7110e086e5f98757ff05d0b64b59bafc94ec5ecf1e0","serverId":"fake.local","libraryVersion":"apollo-server-core@2.24.0"}
# 🚀  Server ready at http://localhost:4000/

Generate some traffic:

for i in {1..1000}; do
  curl -s 'http://localhost:4000/' -H 'accept: */*' -H 'content-type: application/json' --data-raw '{"query":"{ books { title } }"}'
  sleep 0.2
done

Let it run for a few minutes. Studio will report the initial burst of traffic followed by silence:

The fix, revert to apollo-server-core@2.23.0:

# Get the working version
git checkout fixed
yarn

# Restart the app
# Note "libraryVersion": "apollo-server-core@2.23.0" in the output
node index.js                         
# Apollo usage reporting starting! See your graph at https://studio.apollographql.com/graph/Debugging-data-reporting/?variant=current
# Apollo schema reporting starting! See your graph at https://studio.apollographql.com/graph/Debugging-data-reporting/?variant=current with server info {"bootId":"19f14b66-30fd-4f26-bf25-5a873d9229df","graphVariant":"current","platform":"local","runtimeVersion":"node v12.22.1","executableSchemaId":"4290076ab12ba8e295d7d7110e086e5f98757ff05d0b64b59bafc94ec5ecf1e0","serverId":"fake.local","libraryVersion":"apollo-server-core@2.23.0"}
# 🚀  Server ready at http://localhost:4000/

Then generate some traffic again, as above, let it run for a few minutes and you'll get a much healthier graph:

[molomby]

@jsegaran and/or @glasser you might be interested in this.

[glasser]

Thanks, I'll take a look soon. For what it's worth — the studio usage reporting ingress happily accepts traces and stats from all users, and combines them all into stats. ie, you can send traces to a free graph and it should affect the stats (that's the only way it worked before 2.24!). So the issue isn't exactly what you think it is (Studio completely ignoring data sent as traces).

[molomby]

Awesome, thanks. And yes indeed, a lot of this is speculation on my part so may have missed the mark.

Note though, I was able to get 2.24 working with Studio by digging into node_modules and commenting out this one line, disabling the logic that determines whether to send traces or not. So it's defs something in that general area.

[glasser]

Thanks @molomby. This is a problem inside Studio's servers. We'll get it fixed within the hour. https://status.apollographql.com/incidents/8h2h9kcyty7b

This problem affects all graphs but affects free graphs more. Basically, if any individual message has only stats and no traces, we're throwing it out. Should have set off our monitoring but didn't for technical reasons. The fix is entirely in Studio's servers.

[glasser]

I think this is fixed. Can you check? No code change needed on your end.