Merge #149637

149637: sqlccl: log cancelled stmts in TestExplainGist r=yuzefovich a=yuzefovich

We just saw a test failure that wasn't reproducible by simply rerunning the test with the seed that was reported on the issue. This is the case since we have some non-determinism in sqlsmith that we haven't fully fleshed out. This test is aware of the non-determinism, so it attempts to keep track of the successful stmts which are printed out on a test failure, but in this case this was also insufficient. The query that hit an internal error attempts to reference a column that isn't in the CREATE TABLE, so it must have been added as a schema change, but we don't see it in the log of successful statements. TestExplainGist executes all stmts with 0.1s statement timeout (because initially it was envisioned as the stress of plan-gist logic, so we wanted to have some change in the DB state, but we didn't care much whether all changes would actually apply), so many schema changes are probably canceled before they can complete. This commit makes it so that we now also track all such cancelled statements which we print out in the commented out form on a test failure.

Additionally, this commit skips a couple of known test failures that have reproductions to reduce the noise.

Informs: #149552.
Epic: None

Release note: None

Co-authored-by: Yahor Yuzefovich <[email protected]>

Author: craig[bot]

pkg/ccl/testccl/sqlccl/explain_test.go

@@ -160,14 +160,23 @@ func TestExplainGist(t *testing.T) {
 
 		// Given that statement timeout might apply differently between test
 		// runs with the same seed (e.g. because of different CPU load), we'll
-		// accumulate all successful statements for ease of reproduction.
-		var successfulStmts strings.Builder
-		logStmt := func(stmt string) {
-			successfulStmts.WriteString(stmt)
-			successfulStmts.WriteString(";\n")
+		// accumulate all statements for ease of reproduction.
+		var stmts strings.Builder
+		logStmt := func(stmt string, successful bool) {
+			if !successful {
+				// Comment out the canceled stmt since its effects might not
+				// have applied, but we still might need to know it for
+				// reproduction.
+				//
+				// Also replace newline characters with tabs so that it takes
+				// only a single line.
+				stmt = "-- cancelled:\t" + strings.ReplaceAll(stmt, "\n", "\t")
+			}
+			stmts.WriteString(stmt)
+			stmts.WriteString(";\n")
 		}
 		for _, stmt := range setup {
-			logStmt(stmt)
+			logStmt(stmt, true /* successful */)
 		}
 
 		smither, err := sqlsmith.NewSmither(sqlDB, rng, sqlsmith.SimpleNames())
@@ -190,15 +199,17 @@ func TestExplainGist(t *testing.T) {
 			if err != nil && strings.Contains(err.Error(), "internal error") {
 				// Ignore all errors except the internal ones.
 				for _, knownErr := range []string{
-					"expected equivalence dependants to be its closure", // #119045
+					"expected equivalence dependants to be its closure",                  // #119045
+					"argument expression has type RECORD, need type USER DEFINED RECORD", // #139910
+					"not in index", // #148405
 				} {
 					if strings.Contains(err.Error(), knownErr) {
 						// Don't fail the test on a set of known errors.
 						return
 					}
 				}
-				t.Log(successfulStmts.String())
-				t.Fatalf("%v: %s", err, stmt)
+				t.Log(stmts.String())
+				t.Fatalf("%v:\n%s;", err, stmt)
 			}
 		}
 
@@ -288,11 +299,12 @@ func TestExplainGist(t *testing.T) {
 			case err = <-errCh:
 				if err != nil {
 					checkErr(err, stmt)
+					logStmt(stmt, false /* successful */)
 				} else {
-					logStmt(stmt)
+					logStmt(stmt, true /* successful */)
 				}
 			case <-time.After(time.Minute):
-				t.Log(successfulStmts.String())
+				t.Log(stmts.String())
 				sl := allstacks.Get()
 				t.Logf("stacks:\n\n%s", sl)
 				t.Fatalf("stmt wasn't canceled by statement_timeout of 0.1s - ran at least for 1m: %s", stmt)