pkg/ccl/testccl/sqlccl/sqlccl_test: TestShowCreateRedactableValues failed

[cockroach-teamcity]

pkg/ccl/testccl/sqlccl/sqlccl_test.TestShowCreateRedactableValues failed with artifacts on master @ ef87a4e4816fc6a208b78307221ec56667123877:

Fatal error:

panic: test timed out after 4m57s
running tests:
	TestShowCreateRedactableValues (4m57s)

Stack:

goroutine 19900 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2366 +0x30c
created by time.goFunc
	GOROOT/src/time/sleep.go:177 +0x38

Log preceding fatal error

=== RUN   TestShowCreateRedactableValues
    test_log_scope.go:170: test logs captured to: /artifacts/tmp/_tmp/3aad4e00c7d41d09dee6369c20f680d0/logTestShowCreateRedactableValues1320363723
    test_log_scope.go:81: use -show-logs to present logs inline
    show_create_test.go:35: seed: 1521703548986163053
    show_create_test.go:81: SET CLUSTER SETTING sql.stats.automatic_collection.enabled = false;
    show_create_test.go:81: SET CLUSTER SETTING sql.stats.histogram_collection.enabled = false;
    show_create_test.go:81: CREATE TABLE "tabl\\u8FDCe_1" (col1_0 CHAR, col1_1 INT2 NOT NULL, "co l1%p_2" BOX2D NULL, "col1'_3" VARCHAR NOT NULL, col1_4 TIMESTAMPTZ, co̕l1_5 OID NULL, "
col1_6" GEOMETRY NOT NULL, col1_7 BYTES NOT NULL, "co""l1_8" TIMESTAMP NOT NULL, col1_9 STRING COLLATE en_US NOT NULL, 😳col1_10 BIT(15) NOT NULL, col1_11 TIME NOT NULL, "c%vol1_12" REGROLE NULL, col1̳_13 TIME NOT NULL, col1̈_14 PG_LSN, colͩ1_15 BOOL NULL, col1_16 STRING AS (CASE WHEN col1_4 IS NULL THEN 'allosaurus}jH6F':::STRING ELSE 'allosaurusJUg2Gzb':::STRING END) STORED, c͐ol1_17 STRING NOT NULL AS (lower(CAST(col1_9 AS STRING))) VIRTUAL, INDEX (col1_1 DESC, "co""l1_8") WHERE (((((((("tabl\\u8FDCe_1".col1_16 <= 'allosaurus':::STRING) AND ("tabl\\u8FDCe_1".col1_1 >= 1:::INT8)) AND ("tabl\\u8FDCe_1".col1_0 <= 'allosaurus"':::STRING)) OR ("tabl\\u8FDCe_1"."col1'_3" >= e'allosaurus\x00':::STRING)) OR ("tabl\\u8FDCe_1".c͐ol1_17 >= e'\'':::STRING)) OR (NOT "tabl\\u8FDCe_1".colͩ1_15)) AND ("tabl\\u8FDCe_1".col1_11 <= '00:00:00':::TIME)) AND ("tabl\\u8FDCe_1".col1_4 != '2001-01-01 00:00:00+00 BC':::TIMESTAMPTZ)) AND ("tabl\\u8FDCe_1".col1_7 <= '\x':::BYTES), FAMILY (colͩ1_15), FAMILY ("c%vol1_12"), FAMILY ("co""l1_8"), FAMILY ("co l1%p_2", col1̳_13, "
col1_6"), FAMILY (col1̈_14), FAMILY (col1_7), FAMILY (col1_0, col1_9), FAMILY (col1_1), FAMILY (col1_16, 😳col1_10), FAMILY (col1_11), FAMILY (co̕l1_5, "col1'_3", col1_4))
    show_create_test.go:81: CREATE TABLE table_2 (col2_0 STRING NOT NULL, "cOl 2_1" TIMESTAMP NOT NULL, "co l2_2" STRING NOT NULL, col2̧_3 NAME, co😁l2_4 REGTYPE NULL, PRIMARY KEY ("co l2_2" ASC))
    show_create_test.go:81: CREATE TABLE table_3 (col3_0 BOOL NOT NULL, "coL3!_1" INTERVAL NOT NULL, col3_2 BIT(15) NOT NULL, col3_3 TIME NOT NULL, col3_4 BIT(15) NOT NULL, "col3 _5" CHAR NOT NULL, "co""l3%p_6" STRING NOT NULL, " c ol3_7" STRING NOT NULL AS (lower("col3 _5")) VIRTUAL, PRIMARY KEY ("coL3!_1", col3_4 DESC, col3_2 DESC, col3_3 DESC, "col3 _5" ASC, col3_0 ASC, " c ol3_7"), UNIQUE (col3_0 ASC, lower("co""l3%p_6") DESC, lower(CAST(col3_0 AS STRING)) DESC), INDEX (col3_2 ASC), FAMILY (col3_4, col3_0, col3_3), FAMILY (col3_2, "col3 _5", "coL3!_1", "co""l3%p_6"))
    show_create_test.go:81: ALTER TABLE "tabl\\u8FDCe_1" INJECT STATISTICS e'[{"avg_size": 5, "columns": ["col1_0"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 950332204810128431, "histo_col_type": "", "name": "__auto__", "null_count": 680637053691721155, "row_count": 2384908064970189971}, {"avg_size": 1, "columns": ["col1_1"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1791498275855586033, "histo_buckets": [{"distinct_range": 0, "num_eq": 7379508277164450345, "num_range": 0, "upper_bound": "30663"}, {"distinct_range": 62231840.37191542, "num_eq": 60000, "num_range": 80000000, "upper_bound": "13786"}, {"distinct_range": 1511937287445511200, "num_eq": 40, "num_range": 8944462030853350037, "upper_bound": "23578"}, {"distinct_range": 6644.086299956079, "num_eq": 800000000, "num_range": 9000, "upper_bound": "-2215"}, {"distinct_range": 872697461672645900, "num_eq": 7795554109520099260, "num_range": 872697461672645933, "upper_bound": "1768"}, {"distinct_range": 0, "num_eq": 600, "num_range": 6000000000, "upper_bound": "-24682"}], "histo_col_type": "INT2", "histo_version": 3, "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 10, "columns": ["\\"co l1%p_2\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 144527329708341180, "histo_col_type": "", "name": "__auto__", "null_count": 1638386743892889349, "row_count": 2384908064970189971}, {"avg_size": 17, "columns": ["\\"col1\'_3\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1667190121787168526, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 2, "columns": ["col1_4"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1182326750887188573, "histo_col_type": "", "name": "__auto__", "null_count": 1763266492298914560, "row_count": 2384908064970189971}, {"avg_size": 10, "columns": ["co\u0315l1_5"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 663502491164700318, "histo_col_type": "", "name": "__auto__", "null_count": 70973625706435801, "row_count": 2384908064970189971}, {"avg_size": 1, "columns": ["\\"\\rcol1_6\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 356918590667294856, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 20, "columns": ["col1_7"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 196750353756915806, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 25, "columns": ["\\"co\\"\\"l1_8\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1729769705919902145, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 23, "columns": ["col1_9"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 199858816508504231, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 9, "columns": ["\U0001F633col1_10"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 814308288062412136, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 11, "columns": ["col1_11"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 713521256924234342, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 12, "columns": ["\\"c%vol1_12\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1933287234090626768, "histo_col_type": "", "name": "__auto__", "null_count": 1217762089860370326, "row_count": 2384908064970189971}, {"avg_size": 18, "columns": ["col1\u0333_13"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 42049969280490288, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}, {"avg_size": 16, "columns": ["col1\u0308_14"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 244168707825897667, "histo_col_type": "", "name": "__auto__", "null_count": 1385012191077077063, "row_count": 2384908064970189971}, {"avg_size": 17, "columns": ["col\u03691_15"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 166518431478512422, "histo_col_type": "", "name": "__auto__", "null_count": 2196676754195837901, "row_count": 2384908064970189971}, {"avg_size": 17, "columns": ["col1_16"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1525649011347520223, "histo_col_type": "", "name": "__auto__", "null_count": 2121647748540106395, "row_count": 2384908064970189971}, {"avg_size": 14, "columns": ["c\u0350ol1_17"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1097267597740606471, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2384908064970189971}]':::JSONB
    show_create_test.go:81: ALTER TABLE table_2 INJECT STATISTICS e'[{"avg_size": 8, "columns": ["col2_0"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 24280769116, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 40000000000}, {"avg_size": 19, "columns": ["\\"cOl 2_1\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 13467012563, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 40000000000}, {"avg_size": 9, "columns": ["\\"co l2_2\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 558260182, "histo_buckets": [{"distinct_range": 0, "num_eq": 10000, "num_range": 0, "upper_bound": "y"}, {"distinct_range": 0, "num_eq": 90000000, "num_range": 0, "upper_bound": "\\u0007P!"}, {"distinct_range": 0, "num_eq": 1440700016011010839, "num_range": 0, "upper_bound": "<*]BF\\u001a\\u0001"}, {"distinct_range": 0, "num_eq": 338350738189468173, "num_range": 307071203190966032, "upper_bound": "5\\u0015Dz=\\u0018\\u0011Ny"}], "histo_col_type": "STRING", "histo_version": 3, "name": "__auto__", "null_count": 0, "row_count": 40000000000}, {"avg_size": 26, "columns": ["col2\u0327_3"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 6921377853, "histo_col_type": "", "name": "__auto__", "null_count": 13929975701, "row_count": 40000000000}, {"avg_size": 13, "columns": ["co\U0001F601l2_4"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 6595102325, "histo_col_type": "", "name": "__auto__", "null_count": 30028730338, "row_count": 40000000000}]':::JSONB
    show_create_test.go:81: ALTER TABLE table_3 INJECT STATISTICS e'[{"avg_size": 26, "columns": ["col3_0"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1153422457, "histo_buckets": [{"distinct_range": 0, "num_eq": 2000, "num_range": 0, "upper_bound": "true"}, {"distinct_range": 2346827856238469600, "num_eq": 20000000, "num_range": 2346827856238469419, "upper_bound": "false"}], "histo_col_type": "BOOL", "histo_version": 3, "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 26, "columns": ["\\"coL3!_1\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1807048853, "histo_buckets": [{"distinct_range": 0, "num_eq": 2616782673788765386, "num_range": 0, "upper_bound": "-65 years -2 mons -824 days -09:02:51.127267"}], "histo_col_type": "INTERVAL", "histo_version": 3, "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 28, "columns": ["col3_2"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 496059235, "histo_buckets": [{"distinct_range": 0, "num_eq": 7429325144470036437, "num_range": 0, "upper_bound": "100000011010101"}, {"distinct_range": 0, "num_eq": 8385973606854395224, "num_range": 9031173645207751171, "upper_bound": "100100110100010"}], "histo_col_type": "BIT(15)", "histo_version": 3, "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 31, "columns": ["col3_3"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 1465199330, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 29, "columns": ["col3_4"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 316078838, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 28, "columns": ["\\"col3 _5\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 618628950, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 24, "columns": ["\\"co\\"\\"l3%p_6\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 556037965, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2000000000}, {"avg_size": 30, "columns": ["\\" c ol3_7\\""], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 903310222, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 2000000000}]':::JSONB
    show_create_test.go:81: CREATE TYPE rand_typ_0 AS ENUM ('txzseu', 'n')
    show_create_test.go:81: CREATE TYPE rand_typ_1 AS ENUM ('rd', 'tbjpan', 'ytk', 'atqxxg')
    show_create_test.go:81: CREATE TYPE rand_typ_2 AS ENUM ('e', 'yq')
    show_create_test.go:81: SET statement_timeout = '30s';
    show_create_test.go:103: ALTER TABLE defaultdb.public."tabl\\u8FDCe_1" ALTER COLUMN col1̳_13 SET DATA TYPE OID
    show_create_test.go:106: -- ignoring error: pq: cannot convert TIME to OID
    show_create_test.go:103: CREATE SEQUENCE defaultdb.public."'seq_1"
    show_create_test.go:103: CREATE FUNCTION fu😏nc_1(IN p0 INET, INOUT p1 VARCHAR DEFAULT e'allosaurus5\x13j\x18<\r\x0epi':::STRING, p2 REGROLE DEFAULT 0:::OID, IN p3 REGPROC DEFAULT 3588494616:::REGPROC, p4 INET DEFAULT 'f174:ea87:81ff:cb81:2746:3795:45fa:c1e1/11':::INET, INOUT p5 BOOL DEFAULT (NULL::INET >> 'ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff':::INET::INET)::BOOL, p6 INTERVAL DEFAULT '39 years 8 mons 905 days 12:59:39.062315':::INTERVAL)
        	RETURNS SETOF RECORD
        	LANGUAGE SQL
        	CALLED ON NULL INPUT
        	STABLE
        	AS $funcbody$
        SELECT NULL AS col_1, '9683D3D4/1E060CC':::PG_LSN AS "c	ol_2", "🙃tab\\U000B62E6_3"."co l1%p_2" AS col_3, "🙃tab\\U000B62E6_3"."co""l1_8" AS "c ol_4" FROM defaultdb.public."tabl\\u8FDCe_1"@"tabl\\u8FDCe_1_col1_1_co""l1_8_idx" AS "🙃tab\\U000B62E6_3";
        SELECT count(*) AS "coL_5" FROM defaultdb.public.table_2@[0] AS "tab\\U000AA5FC_4" GROUP BY "tab\\U000AA5FC_4"."co l2_2" ORDER BY "tab\\U000AA5FC_4"."co l2_2";
        SELECT p6 AS "c'o%vl_6", p4 AS col_7, p4 AS col_8 FROM defaultdb.public.table_2 AS "t\\U00035CBAa'b_5" JOIN defaultdb.public.table_2 AS "t\\x0cab_6" ON ("t\\U00035CBAa'b_5"."co l2_2") = ("t\\x0cab_6"."co l2_2") ORDER BY "t\\U00035CBAa'b_5"."co l2_2" ASC NULLS FIRST, "t\\U00035CBAa'b_5"."co l2_2" DESC, "t\\U00035CBAa'b_5"."co l2_2" ASC NULLS LAST LIMIT 11:::INT8;
        SELECT p1 AS col_9, p5 AS col_10, p3 AS col_11, p6 AS col_12, "taB_7".tableoid AS col_13, "taB_7"."cOl 2_1" AS col_14, 3469380952:::OID AS col_15 FROM defaultdb.public.table_2@[0] AS "taB_7" WHERE "taB_7".col2_0 NOT ILIKE "taB_7".col2_0 ORDER BY "taB_7".co😁l2_4 DESC NULLS FIRST, "taB_7".crdb_internal_mvcc_timestamp ASC NULLS LAST LIMIT 58:::INT8;
        SELECT (SELECT NULL AS col_16 FROM defaultdb.public.table_3 AS tab_9 JOIN defaultdb.public.table_3 AS "t\\u1C2Cab😭_10" ON (tab_9."coL3!_1") = ("t\\u1C2Cab😭_10"."coL3!_1") LIMIT 1:::INT8) AS col😲_17 FROM defaultdb.public.table_2@table_2_pkey AS "ta	b_8" LIMIT 69:::INT8
        $funcbody$
    show_create_test.go:103: ALTER TABLE defaultdb.public."tabl\\u8FDCe_1" ALTER PRIMARY KEY USING COLUMNS ("co""l1_8")

Help

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

This test on roachdash | Improve this report!

Jira issue: CRDB-38353

[yuzefovich]

This is stuck retrying ALTER PRIMARY KEY statement (see logs. Starting with

I240502 06:02:10.458467 1695 sql/conn_executor.go:4397 â‹® [T1,Vsystem,n1,client=127.0.0.1:52354,hostssl,user=root] 202  queued new schema change job 965212013781909505 using the new schema changer
I240502 06:02:10.486286 1695 5@util/log/event_log.go:32 ⋮ [T1,Vsystem,n1,client=127.0.0.1:52354,hostssl,user=root] 203 ={"Timestamp":1714629730338070653,"EventType":"alter_table","Statement":"ALTER TABLE ‹defaultdb›.public.‹\"tabl\\\\u8FDCe_1\"› ALTER PRIMARY KEY USING COLUMNS (‹\"co\"\"l1_8\"›)","Tag":"ALTER TABLE","User":"root","DescriptorID":104,"TableName":"‹defaultdb.public.\"tabl\\\\u8FDCe_1\"›","MutationID":1}

First error is

W240502 06:02:11.348034 3743 sql/schemachanger/scrun/scrun.go:139 ⋮ [T1,Vsystem,n1,job=‹NEW SCHEMA CHANGE id=965212013781909505›] 242  failed executing declarative schema change PostCommitNonRevertiblePhase stage 3 of 4 with 22 MutationType ops (rollback=false) for ALTER TABLE with error: executing declarative schema change PostCommitNonRevertiblePhase stage 3 of 4 with 22 MutationType ops (rollback=false) for ALTER TABLE: error executing ‹PostCommitNonRevertiblePhase stage 3 of 4 with 22 MutationType ops›: relation ‹"tabl\\\\u8FDCe_1"› (104): index ID 2 found in depended-on-by references, no such index in this relation

I think this is a dup of #123017 since we also set a statement timeout in this test. Closing as a dup, cc @rafiss for awareness