pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed

[cockroach-teamcity]

pkg/sql/sqlstats/sqlstats_test.TestDataDrivenTest failed on master @ e08f3f63de8991e55b632e94ecbf169e68a98221:

=== RUN   TestDataDrivenTest
    test_log_scope.go:172: test logs captured to: outputs.zip/logTestDataDrivenTest3794338179
    test_log_scope.go:82: use -show-logs to present logs inline
    sqlstats_test.go:99: -- test log scope end --
test logs left over in: outputs.zip/logTestDataDrivenTest3794338179
--- FAIL: TestDataDrivenTest (96.37s)
=== RUN   TestDataDrivenTest/plpgsql
    test_server_shim.go:168: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    sqlstats_test.go:73: error executing query="CREATE TABLE IF NOT EXISTS test(a int);\n  CREATE OR REPLACE PROCEDURE insert_incremental(n INT)\n  LANGUAGE plpgsql\n  AS $$\n  DECLARE\n    i INT := 0;\n    next_val INT;\n  BEGIN\n    WHILE i < n LOOP\n      SELECT coalesce(max(a), 0) + 1 INTO next_val FROM test;\n      INSERT INTO test(a) VALUES (next_val);\n      i := i + 1;\n    END LOOP;\n  END;\n  $$;\nCALL insert_incremental(5);" args=[]: pq: function 107 does not exist
    datadriven.go:343: 
        fatal during /mnt/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/sql/sqlstats/sqlstats_test_/sqlstats_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/sqlstats/testdata/plpgsql:1:
        CREATE TABLE IF NOT EXISTS test(a int);
          CREATE OR REPLACE PROCEDURE insert_incremental(n INT)
          LANGUAGE plpgsql
          AS $$
          DECLARE
            i INT := 0;
            next_val INT;
          BEGIN
            WHILE i < n LOOP
              SELECT coalesce(max(a), 0) + 1 INTO next_val FROM test;
              INSERT INTO test(a) VALUES (next_val);
              i := i + 1;
            END LOOP;
          END;
          $$;
        CALL insert_incremental(5);
--- FAIL: TestDataDrivenTest/plpgsql (24.99s)

Parameters:

• attempt=1
• race=true
• run=1
• shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/obs-prs

This test on roachdash | Improve this report!

Jira issue: CRDB-64858

[dhartunian]

/investigate

[github-actions]

Investigation: TestDataDrivenTest/plpgsql

Investigated failure: #171723
Failure SHA: e08f3f63de8991e55b632e94ecbf169e68a98221
Confidence: moderate

What This Test Does

TestDataDrivenTest in pkg/sql/sqlstats is a data-driven test that verifies SQL statement and transaction statistics are correctly recorded. The plpgsql subtest creates a PL/pgSQL stored procedure (insert_incremental) using CREATE OR REPLACE PROCEDURE, calls it with CALL insert_incremental(5), and then asserts that the recorded statement statistics match expected values. All three SQL statements (CREATE TABLE, CREATE OR REPLACE PROCEDURE, CALL) are sent as a single Simple Query batch via execSqlRunner.Exec(t, d.Input).

Where the Failure Occurs

The failure occurs at sqlstats_test.go:73, which executes the multi-statement batch. The error is:

pq: function 107 does not exist

This error originates from getters.go:156 in ByIDGetter.Function(), where the descriptor for function ID 107 is looked up by ID but returns catalog.ErrDescriptorNotFound. The CALL insert_incremental(5) statement successfully resolves the procedure name to descriptor ID 107 via namespace lookup, but the subsequent descriptor fetch by ID fails.

Analysis

Hypothesis: Descriptor lease visibility race between CREATE OR REPLACE PROCEDURE and CALL in a Simple Query batch on a shared-process virtual cluster (moderate confidence)

Evidence from the EngFlow artifact logs reveals several key findings:

1. The plpgsql subtest ran on a shared-process virtual cluster (automatically injected a shared process virtual cluster under test), which adds a layer of lease indirection for descriptor visibility.

2. The CREATE PROCEDURE ran twice on the same goroutine (7956):

   • First invocation: StatementPhase completed at 10:26:13.874 (line 2730 of server log) — no PreCommitPhase logged.
   • Second invocation: StatementPhase completed at 10:26:18.112 (line 3452) — no PreCommitPhase logged either.
   • This pattern indicates the implicit transaction containing CREATE OR REPLACE PROCEDURE hit a retryable error after the StatementPhase, was automatically retried, and the second attempt's implicit transaction also did not successfully commit before the test failed.

3. The test ran with race=true, which significantly slows goroutine scheduling and widens timing windows. The metamorphic constant conn-executor-force-exec-with-pausable-portal was set to true, which forces the pausable portal execution path even for non-pausable portals.

4. The descriptor ID 107 was never assigned during the plpgsql subtest. The server logs show DescriptorID 106 was assigned to the test table (line 2007). No create_function event log was emitted for the procedure on the virtual tenant (T10) during the plpgsql subtest. DescriptorID 107 only appears later in the udf subtest (line 5516), which runs on a different server instance. This means the CREATE PROCEDURE's implicit transaction never fully committed.

5. The CALL statement resolved the procedure name to ID 107 via the schema's Functions namespace map, which was populated during the StatementPhase of the CREATE PROCEDURE. However, since the transaction containing the CREATE PROCEDURE had not fully committed (no PreCommitPhase or PostCommitPhase completed), the descriptor at ID 107 was not yet visible through the lease manager. The ByIDGetter.Function() call returned ErrDescriptorNotFound.

Root cause mechanism: In the pgwire Simple Query protocol, multiple statements in a single query string are executed sequentially, each in its own implicit transaction. The CREATE OR REPLACE PROCEDURE runs in one implicit transaction and CALL runs in the next. Between these two implicit transactions, the procedure descriptor must be fully committed and visible through the lease manager. On a shared-process virtual cluster under race conditions, the window between the CREATE PROCEDURE's transaction committing and the descriptor becoming leasable can be insufficient, causing the CALL to resolve the name but fail to fetch the descriptor.

This is a known, recurring flake. The identical error signature (pq: function 107 does not exist) has been seen in the prior closed issue #169628 (May 2026) with the same test, same subtest, and same failure mode.

Related Issues and PRs

• #169628 (closed) — Same test, same subtest, same error (pq: function 107 does not exist). Occurred twice (at SHAs 5b0bc8ba6eb and 152c95d20a52). Was closed after not reproducing locally. The prior investigation identified the same descriptor lease visibility race hypothesis.
• #171433 (open) — Same test on release-26.2, but different failure mode: count: 2 instead of count: 1 for CREATE TABLE IF NOT EXISTS. That failure was attributed to an implicit transaction retry causing double-counted statement statistics.
• #169268 — catalog/lease: fix missing observer notifications on rangefeed updates — merged at the first failure SHA in pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #169628. Changes how lease manager observer events are delivered, potentially affecting descriptor visibility timing.

Timeline

• 2025-11-25: The plpgsql testdata file was added in commit 1be4e487892 (sql,*: record UDF/SP stats).
• 2026-05-02: First occurrence of function 107 does not exist error in pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #169628 at SHA 5b0bc8ba6eb.
• 2026-05-11: Second occurrence in pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #169628 at SHA 152c95d20a52.
• 2026-06-01: pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #169628 closed after no further reproductions.
• 2026-06-17: Current failure (pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #171723) at SHA e08f3f63de89, same error signature.

Detailed evidence and investigation notes

Log Excerpts

From test.log (run 1, the failing run):

=== RUN   TestDataDrivenTest/plpgsql
    test_server_shim.go:168: automatically injected a shared process virtual cluster under test
    sqlstats_test.go:73: error executing query="CREATE TABLE IF NOT EXISTS test(a int);\n  CREATE OR REPLACE PROCEDURE insert_incremental(n INT)\n  LANGUAGE plpgsql\n  AS $$\n  ...\n  $$;\nCALL insert_incremental(5);" args=[]: pq: function 107 does not exist
--- FAIL: TestDataDrivenTest/plpgsql (24.99s)

From the CockroachDB server log (goroutine 7956 on T10):

# CREATE TABLE succeeds, DescriptorID 106
10:26:12.694889 7956 event_log.go:90 create_table DescriptorID:106

# First CREATE PROCEDURE - StatementPhase only, no PreCommitPhase
10:26:13.054410 7956 schema_change_plan_node.go:108 done building targets for CREATE PROCEDURE
10:26:13.874806 7956 scrun.go:102 done executing StatementPhase stage 1 of 1 for CREATE PROCEDURE

# Descriptor lease releases (between implicit transactions)
10:26:16.607650 7956 descriptor_state.go:341 release: 1("system") ver=1
10:26:16.607807 7956 descriptor_state.go:341 release: 3("descriptor") ver=1

# Second CREATE PROCEDURE - also StatementPhase only
10:26:16.940530 7956 scbuild/event_log.go:61 targets built for CREATE PROCEDURE
10:26:18.112773 7956 scrun.go:102 done executing StatementPhase stage 1 of 1 for CREATE PROCEDURE

# Server shuts down immediately after (test already failed)
10:26:18.289089 6207 automatic_stats.go:804 quiescing auto stats
10:26:18.325738 7896 server_controller_channel_orchestrator.go:534 propagate-graceful-drain terminating

Code References

• Error origin: getters.go:149-173 — ByIDGetter.Function() returns "function %d does not exist" when ErrDescriptorNotFound.
• Procedure name resolution: The CALL statement resolves the procedure name via schema_resolver.go → GetResolvedFuncDefinition() → schema's Functions map, which returns the descriptor ID. The descriptor is then fetched separately by getDescriptorsByID.
• Test code: sqlstats_test.go:56-73 — the exec-sql handler opens a new connection, sends the entire batch via Exec().
• Metamorphic constants: conn-executor-force-exec-with-pausable-portal=true forces the pausable portal execution path, which may alter transaction commit/retry timing.

Things Ruled Out

• Cross-subtest contamination: Each testdata file creates a new server (sqlstats_test.go:42), so the udf subtest (which also creates DescriptorID 107) cannot interfere with the plpgsql subtest.

• CREATE OR REPLACE dropping the descriptor: Analysis of the declarative schema changer's replaceFunction() in create_function.go shows that CREATE OR REPLACE preserves the existing descriptor ID and does not drop/recreate. However, in this case the procedure doesn't exist yet (first run), so it uses the CREATE path which allocates a new descriptor ID.

• Same failure mode as release-26.2: pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #171433: The release-26.2 issue (release-26.2: pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #171433) had a different error — a stats count mismatch due to implicit transaction retry. The current issue (pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #171723) has the function 107 does not exist error, which is the same as pkg/sql/sqlstats/sqlstats_test: TestDataDrivenTest failed #169628.

• autocommit_before_ddl: The maybeAutoCommitBeforeDDL function at conn_executor_ddl.go:57 requires explicitTxn || firstStmtExecuted for Case 1. For each implicit transaction in the batch, the DDL is the first (and only) statement, so this path does not fire.

Other Failure Occurrences

Three occurrences across two issues, all with the same error signature:

Date	Issue	SHA	Error	Virtual Cluster Type
2026-05-02	#169628	5b0bc8ba6eb	function 107 does not exist	shared process
2026-05-11	#169628	152c95d20a5	function 107 does not exist	shared process
2026-06-17	#171723	e08f3f63de8	function 107 does not exist	shared process

All three failures occurred under race=true on a shared-process virtual cluster. The error is always function 107 does not exist, suggesting the same descriptor lease visibility race.

Tooling Feedback

• Could not check out the failure SHA (e08f3f63de8991e55b632e94ecbf169e68a98221) because it was not reachable from this remote (blobless clone limitation for private repo commits). Analysis was based on the master branch tip, which is close to the failure SHA.
• The EngFlow artifact download worked well and provided detailed server logs that were critical for the investigation.

---

Workflow run

Was this investigation helpful? Leave a 👍 or 👎 on this comment.

[kyle-a-wong]

Independent investigation — re-routing to SQL Foundations

I dug into the EngFlow artifacts for the failing invocation (dea40539) and reached a different conclusion than the automated /investigate comment above. Summary: this is not an Observability bug and not the "descriptor lease visibility race" described earlier. It's a divergence bug in the pausable-portal execution path's handling of a transaction retry of a CREATE OR REPLACE PROCEDURE. Reassigning to T-sql-foundations.

What actually happened (failing run = run 1)

On the plpgsql subtest's server (each subtest starts a fresh server, so descriptor IDs reset): udf_test db = 104, public schema = 105, table test = 106, procedure insert_incremental = 107. So 107 is the procedure on this server.

• 10:26:12.69 — CREATE TABLE commits cleanly (event logged, ID 106).
• 10:26:13.87 — CREATE OR REPLACE PROCEDURE runs its declarative-schema-changer StatementPhase (allocates 107, adds it to schema 105's function map).
• 10:26:16.51 — failed to repropose ... r97 ... raft on tenant 10's table range — a race=true-induced KV stall that forces a transaction retry.
• 10:26:16.94→18.11 — CREATE PROCEDURE's StatementPhase runs a second time (the retry). No create_function event and no commit are ever emitted.
• The CALL insert_incremental(5) then fails with function 107 does not exist: name→ID resolution found 107 in the schema's function map, but the descriptor-by-ID fetch (descs.ByIDGetter.Function, pkg/sql/catalog/descs/getters.go:156) couldn't see 107.

The smoking gun — three runs of the shard

Run	force-exec-with-pausable-portal	race-induced retry?	plpgsql
1	true	yes	FAIL function 107 does not exist
2	false	no	PASS
3	true	no	PASS

The failure requires both: (1) conn-executor-force-exec-with-pausable-portal = true — a test-only metamorphic constant whose documented purpose is "to force execStmtInOpenStateWithPausablePortal … even for non-pausable portals … to ensure the behavior of the former does not diverge from the latter" (pkg/sql/conn_executor_exec.go:98-104); and (2) a transaction retry (here, race=true KV timing). Run 3 had the pausable path forced but no retry → passed; run 2 had no forcing → passed. Only run 1 hit both.

Root cause

Under the pausable-portal code path, when the implicit transaction for CREATE OR REPLACE PROCEDURE retries, the descriptor collection is left inconsistent — the parent schema's function map still advertises ID 107, but the function descriptor 107 is no longer installed/committed — so the following CALL resolves the name and then fails the by-ID fetch. The metamorphic constant is doing its job: catching that the pausable path diverges from the normal path on retry.

Where the prior automated analysis went wrong

• It claimed descriptor 107 "was never assigned during the plpgsql subtest" and only appears in the udf subtest. That's a misread — IDs reset per subtest server; the udf subtest's 107 is a different server's random_int. On the plpgsql server, 107 is the procedure.
• Its "descriptor lease visibility race" hypothesis is the wrong mechanism, and it never identified the pausable-portal metamorphic constant + transaction retry as the necessary conditions (the run-2 vs run-1 contrast).

Production reachability / blocker assessment

Low. The trigger needs (a) the pausable-portal path, which production uses only for genuinely pausable (row-limited) portals — not for a simple-query batch containing DDL + CALL — and (b) a race-build timing artifact. It won't reproduce deterministically from the seed alone (COCKROACH_RANDOM_SEED=-4101322670253446912) because it also needs the race-induced retry to land. It is still a genuine pausable-path/retry divergence worth fixing, but it does not appear to be a 26.3 release blocker.

[spilchen]

Triager status

Field	Value
Stage	classify-issue
Run ID	2026-06-18-117
Updated	2026-06-18T12:08:22Z
Confidence (flake)	7/10
Confidence (fix)	—
Result	waiting