PgExecutor cache is not cleared between subscription payloads

[benjie]

Summary

he issue specifically relates to the context[this.$$cache] used by PgExecutor not being reset between subscription payloads. This is specifically a bug in PgExecutor, a false assumption about the appropriateness of caching. This cache should also be cleared just before a new mutation field executes.

https://github.com/graphile/crystal/blob/91e87ab6516490a4cc7b7fc6400efb7623fbd331/grafast/dataplan-pg/src/executor.ts#L403

Steps to reproduce

See https://github.com/benjie/ouch-my-finger/issues/11 for a reproduction.

With my edits; see: https://github.com/benjie/ouch-my-finger/tree/gitrojones-subscription-bug

1. Copy .env.example to .env
2. Run the bash code on line 2 of basic-schema.sql
3. Run yarn serve
4. Issue the following GraphQL request:

subscription ($fooId: Int! = 1) {
  foo(fooId: $fooId) {
    foo {
      createdAt
      fieldToUpdate
      fooId
      id
    }
    event
  }
}

5. psql into the DB and run:

insert into foo DEFAULT VALUES;

update foo set field_to_update = gen_random_uuid();

Expected results

New payload on each subscription update.

Actual results

Initial payload is repeated:

{
  "data": {
    "foo": {
      "foo": {
        "createdAt": "2024-06-04T14:25:03.678681+01:00",
        "fieldToUpdate": null,
        "fooId": 1,
        "id": "WyJGb28iLDFd"
      },
      "event": "UPDATE"
    }
  }
}

Additional context

From the logs:

  @dataplan/pg:PgExecutor:verbose PgExecutor(main) no entry for '[]' in cache Map{} +0ms
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇  @dataplan/pg:PgExecutor:explain # SQL QUERY:
  @dataplan/pg:PgExecutor:explain select
  __auth_can_access__::text as "0",
  (not (__auth_can_access__ is null))::text as "1"
from "public"."auth_can_access"() as __auth_can_access__;
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # PLACEHOLDERS:
  @dataplan/pg:PgExecutor:explain []
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # RESULT:
  @dataplan/pg:PgExecutor:explain [ [ '(t)', 'true' ] ]
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # DURATION
  @dataplan/pg:PgExecutor:explain 0.75ms
  @dataplan/pg:PgExecutor:explain 👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # EXPLAIN
  @dataplan/pg:PgExecutor:explain Function Scan on public.auth_can_access __auth_can_access__  (cost=0.25..0.27 rows=1 width=64) (actual time=0.009..0.009 rows=1 loops=1)
  Output: (__auth_can_access__.*)::text, ((NOT (__auth_can_access__.* IS NULL)))::text
  Function Call: auth_can_access()
Settings: effective_cache_size = '48GB', effective_io_concurrency = '200', jit_optimize_above_cost = '-1', max_parallel_workers = '32', max_parallel_workers_per_gather = '4', random_page_cost = '1.1', work_mem = '10485kB'
Planning Time: 0.008 ms
Execution Time: 0.013 ms
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain  +0ms
LAMBDA RESOLVE [ 1, [Object: null prototype] { can_access: true } ]
  @dataplan/pg:PgExecutor:verbose PgExecutor(main) no entry for '["1"]' in cache Map{} +43s
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇👇  @dataplan/pg:PgExecutor:explain # SQL QUERY:
  @dataplan/pg:PgExecutor:explain select __foo_result__.*
from (select 0 as idx, $1::"int4" as "id0") as __foo_identifiers__,
lateral (
  select
    to_char(__foo__."created_at", 'YYYY-MM-DD"T"HH24:MI:SS.USTZH:TZM'::text) as "0",
    __foo__."field_to_update" as "1",
    __foo__."foo_id"::text as "2",
    __foo_identifiers__.idx as "3"
  from "public"."foo" as __foo__
  where (
    __foo__."foo_id" = __foo_identifiers__."id0"
  )
) as __foo_result__;
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # PLACEHOLDERS:
  @dataplan/pg:PgExecutor:explain [ '1' ]
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # RESULT:
  @dataplan/pg:PgExecutor:explain [ [ '2024-06-04T14:25:03.678681+01:00', null, '1', 0 ] ]
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # DURATION
  @dataplan/pg:PgExecutor:explain 0.69ms
  @dataplan/pg:PgExecutor:explain 👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆👆  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain # EXPLAIN
  @dataplan/pg:PgExecutor:explain Index Scan using foo_pkey on public.foo __foo__  (cost=0.15..2.38 rows=1 width=100) (actual time=0.007..0.007 rows=1 loops=1)
  Output: to_char(__foo__.created_at, 'YYYY-MM-DD"T"HH24:MI:SS.USTZH:TZM'::text), __foo__.field_to_update, (__foo__.foo_id)::text, 0
  Index Cond: (__foo__.foo_id = 1)
  Buffers: shared hit=2
Settings: effective_cache_size = '48GB', effective_io_concurrency = '200', jit_optimize_above_cost = '-1', max_parallel_workers = '32', max_parallel_workers_per_gather = '4', random_page_cost = '1.1', work_mem = '10485kB'
Planning Time: 0.018 ms
Execution Time: 0.013 ms
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain 
  @dataplan/pg:PgExecutor:explain  +43s
  @dataplan/pg:PgExecutor:verbose PgExecutor(main) served '["1"]' from cache: <Deferred> +29s
  @dataplan/pg:PgExecutor:verbose PgExecutor(main) served '["1"]' from cache: <Deferred> +4s
  @dataplan/pg:PgExecutor:verbose PgExecutor(main) served '["1"]' from cache: <Deferred> +7m
  @dataplan/pg:PgExecutor:verbose PgExecutor(main) served '["1"]' from cache: <Deferred> +2s