fix: 慢查询/错误 SQL 日志参数化

.env.example

@@ -33,6 +33,8 @@
 # SQL_MAX_OPEN_CONNS=1000
 # 数据库连接最大生命周期（秒）
 # SQL_MAX_LIFETIME=60
+# 慢查询日志阈值（毫秒），0 表示关闭慢查询日志，超出 0-3600000 范围回退默认值 200
+# SQL_SLOW_THRESHOLD_MS=200
 
 
 # 缓存相关配置

go.mod

@@ -67,7 +67,6 @@ require (
 
 require (
 	github.com/ClickHouse/ch-go v0.65.0 // indirect
-	github.com/ClickHouse/clickhouse-go/v2 v2.32.0 // indirect
 	github.com/bmatcuk/doublestar/v4 v4.6.1 // indirect
 	github.com/casbin/govaluate v1.10.0 // indirect
 	github.com/go-faster/city v1.0.1 // indirect
@@ -107,21 +106,21 @@ require (
 	github.com/fxamacker/cbor/v2 v2.9.0 // indirect
 	github.com/gabriel-vasile/mimetype v1.4.3 // indirect
 	github.com/gin-contrib/sse v0.1.0 // indirect
-	github.com/glebarez/go-sqlite v1.21.2 // indirect
+	github.com/glebarez/go-sqlite v1.21.2
 	github.com/go-audio/audio v1.0.0 // indirect
 	github.com/go-audio/riff v1.0.0 // indirect
 	github.com/go-ole/go-ole v1.2.6 // indirect
 	github.com/go-playground/locales v0.14.1 // indirect
 	github.com/go-playground/universal-translator v0.18.1 // indirect
-	github.com/go-sql-driver/mysql v1.7.0 // indirect
+	github.com/go-sql-driver/mysql v1.7.0
 	github.com/go-webauthn/x v0.1.25 // indirect
 	github.com/goccy/go-json v0.10.2 // indirect
 	github.com/google/go-tpm v0.9.5 // indirect
 	github.com/grafana/pyroscope-go/godeltaprof v0.1.9 // indirect
 	github.com/icza/bitio v1.1.0 // indirect
 	github.com/jackc/pgpassfile v1.0.0 // indirect
 	github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761 // indirect
-	github.com/jackc/pgx/v5 v5.9.2 // indirect
+	github.com/jackc/pgx/v5 v5.9.2
 	github.com/jackc/puddle/v2 v2.2.2 // indirect
 	github.com/jfreymuth/vorbis v1.0.2 // indirect
 	github.com/jinzhu/inflection v1.0.0 // indirect
@@ -163,6 +162,9 @@ require (
 	modernc.org/sqlite v1.40.1 // indirect
 )
 
-require github.com/QuantumNous/new-api/relaykit v0.0.0
+require (
+	github.com/ClickHouse/clickhouse-go/v2 v2.32.0
+	github.com/QuantumNous/new-api/relaykit v0.0.0
+)
 
 replace github.com/QuantumNous/new-api/relaykit => ./relaykit

model/gorm_logger.go

@@ -0,0 +1,86 @@
+package model
+
+import (
+	"errors"
+	"fmt"
+	"io"
+	"log"
+	"os"
+	"time"
+
+	"github.com/ClickHouse/clickhouse-go/v2/lib/proto"
+	"github.com/QuantumNous/new-api/common"
+	sqlitedriver "github.com/glebarez/go-sqlite"
+	"github.com/go-sql-driver/mysql"
+	"github.com/jackc/pgx/v5/pgconn"
+	"gorm.io/gorm"
+	"gorm.io/gorm/logger"
+)
+
+const (
+	defaultSlowThresholdMs = 200
+	maxSlowThresholdMs     = 60 * 60 * 1000
+)
+
+func newGormConfig(prepareStmt bool) *gorm.Config {
+	return &gorm.Config{
+		PrepareStmt: prepareStmt,
+		Logger:      newGormLogger(os.Stdout),
+	}
+}
+
+func newGormLogger(w io.Writer) logger.Interface {
+	slowThresholdMs := common.GetEnvOrDefault("SQL_SLOW_THRESHOLD_MS", defaultSlowThresholdMs)
+	if slowThresholdMs < 0 || slowThresholdMs > maxSlowThresholdMs {
+		common.SysError(fmt.Sprintf("invalid SQL_SLOW_THRESHOLD_MS %d (allowed 0-%d, 0 disables slow query log), using default %d", slowThresholdMs, maxSlowThresholdMs, defaultSlowThresholdMs))
+		slowThresholdMs = defaultSlowThresholdMs
+	}
+	// 在 Writer 层脱敏而非包装 logger.Interface:后者会让 gorm 的 FileWithLineNum
+	// 把所有 SQL 日志的调用点归因到包装层自身,且需转发 ParamsFilter 类型断言。
+	return logger.New(&sanitizedLogWriter{delegate: log.New(w, "\r\n", log.LstdFlags)}, logger.Config{
+		SlowThreshold:             time.Duration(slowThresholdMs) * time.Millisecond,
+		LogLevel:                  logger.Warn,
+		IgnoreRecordNotFoundError: true,
+		ParameterizedQueries:      !common.DebugEnabled,
+		Colorful:                  true,
+	})
+}
+
+// ParameterizedQueries 只过滤 SQL 字符串,驱动错误消息(如 MySQL 1062)同样会
+// 内联数据值,在这里收敛为错误码;DEBUG=true 保留原文。
+type sanitizedLogWriter struct {
+	delegate *log.Logger
+}
+
+func (s *sanitizedLogWriter) Printf(format string, args ...interface{}) {
+	if !common.DebugEnabled {
+		for i, arg := range args {
+			if err, ok := arg.(error); ok {
+				args[i] = sanitizeDBError(err)
+			}
+		}
+	}
+	s.delegate.Printf(format, args...)
+}
+
+// 只收敛数据库服务端生成的驱动错误(消息可能内联数据值);网络/上下文等
+// 其它错误不含查询数据,原样保留以便排障。
+func sanitizeDBError(err error) error {
+	var mysqlErr *mysql.MySQLError
+	if errors.As(err, &mysqlErr) {
+		return fmt.Errorf("mysql error %d", mysqlErr.Number)
+	}
+	var pgErr *pgconn.PgError
+	if errors.As(err, &pgErr) {
+		return fmt.Errorf("postgres error SQLSTATE %s", pgErr.Code)
+	}
+	var chErr *proto.Exception
+	if errors.As(err, &chErr) {
+		return fmt.Errorf("clickhouse error %d", chErr.Code)
+	}
+	var sqliteErr *sqlitedriver.Error
+	if errors.As(err, &sqliteErr) {
+		return fmt.Errorf("sqlite error %d", sqliteErr.Code())
+	}
+	return err
+}

model/gorm_logger_test.go

@@ -0,0 +1,102 @@
+package model
+
+import (
+	"bytes"
+	"fmt"
+	"testing"
+
+	"github.com/ClickHouse/clickhouse-go/v2/lib/proto"
+	"github.com/QuantumNous/new-api/common"
+	"github.com/glebarez/sqlite"
+	"github.com/go-sql-driver/mysql"
+	"github.com/jackc/pgx/v5/pgconn"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm"
+)
+
+// 保护契约:数据库驱动错误消息可能内联数据值,非 DEBUG 下日志只保留错误码。
+func TestSanitizeDBErrorStripsDriverMessage(t *testing.T) {
+	tests := []struct {
+		name   string
+		err    error
+		want   string
+		leaked string
+	}{
+		{
+			name:   "mysql duplicate entry",
+			err:    &mysql.MySQLError{Number: 1062, Message: "Duplicate entry 'secret-value' for key 'users.idx'"},
+			want:   "mysql error 1062",
+			leaked: "secret-value",
+		},
+		{
+			name:   "postgres unique violation",
+			err:    &pgconn.PgError{Code: "23505", Message: "duplicate key value", Detail: "Key (k)=(secret-value) already exists."},
+			want:   "postgres error SQLSTATE 23505",
+			leaked: "secret-value",
+		},
+		{
+			name:   "clickhouse exception",
+			err:    &proto.Exception{Code: 241, Message: "Memory limit exceeded while processing 'secret-value'"},
+			want:   "clickhouse error 241",
+			leaked: "secret-value",
+		},
+		{
+			name:   "wrapped driver error",
+			err:    fmt.Errorf("exec failed: %w", &mysql.MySQLError{Number: 1064, Message: "syntax error near 'secret-value'"}),
+			want:   "mysql error 1064",
+			leaked: "secret-value",
+		},
+	}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			got := sanitizeDBError(tc.err)
+			require.Error(t, got)
+			assert.Equal(t, tc.want, got.Error())
+			assert.NotContains(t, got.Error(), tc.leaked)
+		})
+	}
+}
+
+func TestSanitizeDBErrorSQLiteDriver(t *testing.T) {
+	db, err := gorm.Open(sqlite.Open(":memory:"), &gorm.Config{})
+	require.NoError(t, err)
+	execErr := db.Exec("INSERT INTO missing_table (k) VALUES (?)", "secret-value").Error
+	require.Error(t, execErr)
+
+	got := sanitizeDBError(execErr)
+	assert.Regexp(t, `^sqlite error \d+$`, got.Error())
+	assert.NotContains(t, got.Error(), "secret-value")
+}
+
+func TestSanitizeDBErrorKeepsNonDriverErrors(t *testing.T) {
+	err := fmt.Errorf("dial tcp 127.0.0.1:3306: connect: connection refused")
+	assert.Equal(t, err, sanitizeDBError(err))
+}
+
+// 保护契约:经 gorm 真实链路,错误日志同时满足 SQL 参数化、驱动错误脱敏、
+// 调用点归因到业务代码;DEBUG=true 恢复参数值与错误原文。
+func TestGormLoggerEndToEndSanitizedOutput(t *testing.T) {
+	previousDebug := common.DebugEnabled
+	t.Cleanup(func() { common.DebugEnabled = previousDebug })
+
+	execQuery := func() string {
+		var buf bytes.Buffer
+		db, err := gorm.Open(sqlite.Open(":memory:"), &gorm.Config{Logger: newGormLogger(&buf)})
+		require.NoError(t, err)
+		db.Exec("SELECT * FROM missing_table WHERE k = ?", "secret-value")
+		return buf.String()
+	}
+
+	common.DebugEnabled = false
+	out := execQuery()
+	assert.Contains(t, out, "k = ?")
+	assert.NotContains(t, out, "secret-value")
+	assert.Contains(t, out, "sqlite error")
+	assert.Contains(t, out, "gorm_logger_test.go")
+
+	common.DebugEnabled = true
+	debugOut := execQuery()
+	assert.Contains(t, debugOut, "secret-value")
+	assert.Contains(t, debugOut, "no such table")
+}

model/main.go

@@ -132,9 +132,7 @@ func chooseDB(envName string, isLog bool) (*gorm.DB, common.DatabaseType, error)
 				return nil, "", fmt.Errorf("%s does not support ClickHouse; use SQLite, MySQL, or PostgreSQL for the primary database and LOG_SQL_DSN for ClickHouse logs", envName)
 			}
 			common.SysLog("using ClickHouse as log database")
-			db, err := gorm.Open(clickhouse.Open(normalizeClickHouseDSN(dsn)), &gorm.Config{
-				PrepareStmt: false,
-			})
+			db, err := gorm.Open(clickhouse.Open(normalizeClickHouseDSN(dsn)), newGormConfig(false))
 			return db, common.DatabaseTypeClickHouse, err
 		}
 		if strings.HasPrefix(dsn, "postgres://") || strings.HasPrefix(dsn, "postgresql://") {
@@ -143,16 +141,12 @@ func chooseDB(envName string, isLog bool) (*gorm.DB, common.DatabaseType, error)
 			db, err := gorm.Open(postgres.New(postgres.Config{
 				DSN:                  dsn,
 				PreferSimpleProtocol: true, // disables implicit prepared statement usage
-			}), &gorm.Config{
-				PrepareStmt: true, // precompile SQL
-			})
+			}), newGormConfig(true))
 			return db, common.DatabaseTypePostgreSQL, err
 		}
 		if strings.HasPrefix(dsn, "local") {
 			common.SysLog("SQL_DSN not set, using SQLite as database")
-			db, err := gorm.Open(sqlite.Open(common.SQLitePath), &gorm.Config{
-				PrepareStmt: true, // precompile SQL
-			})
+			db, err := gorm.Open(sqlite.Open(common.SQLitePath), newGormConfig(true))
 			return db, common.DatabaseTypeSQLite, err
 		}
 		// Use MySQL
@@ -165,16 +159,12 @@ func chooseDB(envName string, isLog bool) (*gorm.DB, common.DatabaseType, error)
 				dsn += "?parseTime=true"
 			}
 		}
-		db, err := gorm.Open(mysql.Open(dsn), &gorm.Config{
-			PrepareStmt: true, // precompile SQL
-		})
+		db, err := gorm.Open(mysql.Open(dsn), newGormConfig(true))
 		return db, common.DatabaseTypeMySQL, err
 	}
 	// Use SQLite
 	common.SysLog("SQL_DSN not set, using SQLite as database")
-	db, err := gorm.Open(sqlite.Open(common.SQLitePath), &gorm.Config{
-		PrepareStmt: true, // precompile SQL
-	})
+	db, err := gorm.Open(sqlite.Open(common.SQLitePath), newGormConfig(true))
 	return db, common.DatabaseTypeSQLite, err
 }