Merge cockroachdb#41149

41149: sql: exec_log protects internal execs behind V(3) r=jordanlewis a=jordanlewis

Previously, the exec_log vmodule would always include all internal
execs. This was pretty annoying for debugging. This change moves
internal execs behind V(3) instead of V(2).

Additionally, it restores the `exec-internal` vs `exec` label
distinction, which had apparently been lost in a refactor at some point.

Release justification: low risk, high benefit changes to existing
functionality
Release note (cli change): the exec_log vmodule now does not log
internally-generated statements unless the vmodule is set to 3 instead
of 2.

Co-authored-by: Jordan Lewis <[email protected]>

pkg/sql/conn_executor.go

@@ -533,7 +533,8 @@ func (s *Server) newConnExecutor(
 
 		// ctxHolder will be reset at the start of run(). We only define
 		// it here so that an early call to close() doesn't panic.
-		ctxHolder: ctxHolder{connCtx: ctx},
+		ctxHolder:    ctxHolder{connCtx: ctx},
+		executorType: executorTypeExec,
 	}
 
 	ex.state.txnAbortCount = ex.metrics.EngineMetrics.TxnAbortCount
@@ -953,6 +954,10 @@ type connExecutor struct {
 	// draining is set if we've received a DrainRequest. Once this is set, we're
 	// going to find a suitable time to close the connection.
 	draining bool
+
+	// executorType is set to whether this executor is an ordinary executor which
+	// responds to user queries or an internal one.
+	executorType executorType
 }
 
 // ctxHolder contains a connection's context and, while session tracing is

pkg/sql/conn_executor_exec.go

@@ -647,7 +647,7 @@ func (ex *connExecutor) dispatchToExecutionEngine(
 	defer func() {
 		planner.maybeLogStatement(
 			ctx,
-			"exec",
+			ex.executorType,
 			ex.extraTxnState.autoRetryCounter,
 			res.RowsAffected(),
 			res.Err(),

pkg/sql/exec_log.go

@@ -88,16 +88,36 @@ var logStatementsExecuteEnabled = settings.RegisterBoolSetting(
 	false,
 )
 
+type executorType int
+
+const (
+	executorTypeExec executorType = iota
+	executorTypeInternal
+)
+
+// vLevel returns the vmodule log level at which logs from the given executor
+// should be written to the logs.
+func (s executorType) vLevel() int32 { return int32(s) + 2 }
+
+var logLabels = []string{"exec", "exec-internal"}
+
+// logLabel returns the log label for the given executor type.
+func (s executorType) logLabel() string { return logLabels[s] }
+
 // maybeLogStatement conditionally records the current statement
 // (p.curPlan) to the exec / audit logs.
 func (p *planner) maybeLogStatement(
-	ctx context.Context, lbl string, numRetries, rows int, err error, queryReceived time.Time,
+	ctx context.Context,
+	execType executorType,
+	numRetries, rows int,
+	err error,
+	queryReceived time.Time,
 ) {
-	p.maybeLogStatementInternal(ctx, lbl, numRetries, rows, err, queryReceived)
+	p.maybeLogStatementInternal(ctx, execType, numRetries, rows, err, queryReceived)
 }
 
 func (p *planner) maybeLogStatementInternal(
-	ctx context.Context, lbl string, numRetries, rows int, err error, startTime time.Time,
+	ctx context.Context, execType executorType, numRetries, rows int, err error, startTime time.Time,
 ) {
 	// Note: if you find the code below crashing because p.execCfg == nil,
 	// do not add a test "if p.execCfg == nil { do nothing }" !
@@ -150,6 +170,8 @@ func (p *planner) maybeLogStatementInternal(
 		auditErrStr = "ERROR"
 	}
 
+	lbl := execType.logLabel()
+
 	// Now log!
 	if auditEventsDetected {
 		logger := p.execCfg.AuditLogger
@@ -163,7 +185,7 @@ func (p *planner) maybeLogStatementInternal(
 	}
 	if logV {
 		// Copy to the main log.
-		log.VEventf(ctx, 2, "%s %q %s %q %s %.3f %d %q %d",
+		log.VEventf(ctx, execType.vLevel(), "%s %q %s %q %s %.3f %d %q %d",
 			lbl, appName, logTrigger, stmtStr, plStr, age, rows, execErrStr, numRetries)
 	}
 }

pkg/sql/internal.go

@@ -194,6 +194,7 @@ func (ie *internalExecutorImpl) initConnEx(
 	if err != nil {
 		return nil, nil, err
 	}
+	ex.executorType = executorTypeInternal
 
 	var wg sync.WaitGroup
 	wg.Add(1)