diff --git a/.env.example b/.env.example index d62e1146..3b8a2a5b 100644 --- a/.env.example +++ b/.env.example @@ -33,6 +33,8 @@ # SQL_MAX_OPEN_CONNS=1000 # 数据库连接最大生命周期(秒) # SQL_MAX_LIFETIME=60 +# 慢查询日志阈值(毫秒),0 表示关闭慢查询日志,超出 0-3600000 范围回退默认值 200 +# SQL_SLOW_THRESHOLD_MS=200 # 缓存相关配置 diff --git a/go.mod b/go.mod index 470e892b..fa0632bc 100644 --- a/go.mod +++ b/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,13 +106,13 @@ 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 @@ -121,7 +120,7 @@ require ( 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 diff --git a/model/gorm_logger.go b/model/gorm_logger.go new file mode 100644 index 00000000..81430730 --- /dev/null +++ b/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 +} diff --git a/model/gorm_logger_test.go b/model/gorm_logger_test.go new file mode 100644 index 00000000..6095e8be --- /dev/null +++ b/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") +} diff --git a/model/main.go b/model/main.go index ac63d1f5..21445593 100644 --- a/model/main.go +++ b/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 }