GORM回调异常：日志插入时参数数量不符问题排查

我在Go应用中尝试跟踪所有针对MySQL数据库的查询，于是在初始化函数中注册了Query阶段全局后置回调full_logger，用于将查询信息写入query_logs表。但遇到了参数注入错误，具体情况如下：

相关代码 #

初始化函数 #

func InitDatabase() error {
    err = DBEnv.Db.Callback().Query().After("*").Register("full_logger", setQueryLogger)
    if err != nil {
        return err
    }
    return nil
}

// Querylogger
func setQueryLogger(db *gorm.DB) {
    sql, vars := db.Statement.SQL.String(), db.Statement.Vars
    rows := db.Statement.RowsAffected
    varsJson, err := json.Marshal(vars)
    if err != nil {
        panic(err)
    }

    db.Exec("INSERT INTO `query_logs` (`sql`,`parameters`, `rows_affected`, `executed_at`, `executed_by`) VALUES (?, ?, ?, ?, ?)", sql, varsJson, rows, time.Now(), 1)
}

User结构体 #

type User struct {
    ID                    uint64         `gorm:"primarykey" json:"id"`
    CreatedAt             time.Time      `json:"createdAt"`
    CreatedBy             uint64         `json:"createdBy" validate:"required,gt=0"`
    UpdatedAt             time.Time      `json:"updatedAt"`
    UpdatedBy             uint64         `json:"updatedBy" validate:"required,gt=0"`
    DeletedAt             gorm.DeletedAt `json:"deletedAt"`
    DeletedBy             sql.NullInt64  `json:"deletedBy" validate:"required_with=DeletedAt"`
    ImportedBy            sql.NullInt64  `json:"importedBy" validate:"required_with=ImportedAt"`
    ImportedAt            sql.NullTime   `json:"importedAt" validate:"required_with=ImportedBy"`
    Email                 string         `json:"email" validate:"required"`
    Password              string         `json:"password" validate:"required"`
    FirstName             string         `json:"firstName" validate:"required"`
    LastName              string         `json:"lastName" validate:"required"`
    Active                bool           `json:"active" validate:"required"`
    LastPasswordChangedAt time.Time      `json:"lastPasswordChangedAt" validate:"required"`
    ActivatedBy           sql.NullInt64  `json:"activatedBy" validate:"required_with=ActivatedAt,gt=0"`
    ActivatedAt           sql.NullTime   `json:"activatedAt" validate:"required_with=ActivatedBy"`
    DeactivatedBy         sql.NullInt64  `json:"deactivatedBy" validate:"required_with=DeactivatedAt,gt=0"`
    DeactivatedAt         sql.NullTime   `json:"deactivatedAt" validate:"required_with=DeactivatedBy"`
    RoleId                uint64         `json:"roleId" validate:"required,gt=0"`
    InstituteId           sql.NullInt64  `json:"instituteId"`
}

查询方法 #

func (u *User) FindFirst() *User {
    db.DBEnv.Db.First(u)
    return u
}

调用代码 #

user3 := (*user.User).FindFirst(&user.User{ID: 3})

问题现象 #

GORM执行的查询语句为：

SELECT * FROM `users` WHERE `users`.`deleted_at` IS NULL AND `users`.`id` = ? ORDER BY `users`.`id`  LIMIT 1

但回调中执行的日志插入语句却变成：

INSERT INTO `query_logs` (`sql`,`parameters`, `rows_affected`, `executed_at`, `executed_by`) VALUES (3, 'SELECT * FROM `users` WHERE `users`.`deleted_at` IS NULL AND `users`.`id` = ? ORDER BY `users`.`id` LIMIT 1', '[3]', 1, '2024-01-29 19:46:35.978')

导致报错：

sql: expected 5 arguments, got 6

疑问 #

为何GORM会将查询的ID作为额外参数注入到db.Exec中？是遗漏了配置还是Bug？

附query_logs表结构：

create table query_logs(
    id bigint unsigned not null primary key auto_increment,
    `sql` text not null,
    `parameters` json null,
    rows_affected bigint unsigned not null default 0,
    executed_at datetime        not null default current_timestamp,
    executed_by bigint unsigned not null,
    foreign key (executed_by) references users (id) on delete restrict on update restrict
) ENGINE = Innodb;

这不是Bug，是因为你在回调中使用的db *gorm.DB实例依然保留着当前查询的上下文（包括原查询的参数），调用db.Exec时，GORM会自动将原Statement.Vars追加到你传入的参数列表中，导致参数数量超出预期。

解决方法 #

你需要创建一个新的DB会话，脱离当前查询的上下文，避免参数被自动追加。修改setQueryLogger函数如下：

func setQueryLogger(db *gorm.DB) {
    sql, vars := db.Statement.SQL.String(), db.Statement.Vars
    rows := db.Statement.RowsAffected
    varsJson, err := json.Marshal(vars)
    if err != nil {
        panic(err)
    }

    // 使用Session创建新的会话，清空当前Statement的上下文
    db.Session(&gorm.Session{}).Exec(
        "INSERT INTO `query_logs` (`sql`,`parameters`, `rows_affected`, `executed_at`, `executed_by`) VALUES (?, ?, ?, ?, ?)",
        sql, varsJson, rows, time.Now(), 1,
    )
}

原理说明 #

GORM的DB实例会携带当前操作的Statement信息，包括查询参数。当你在回调中直接调用db.Exec时，GORM会将原Statement.Vars（也就是查询用户时的[3]）合并到你传入的参数里，最终参数变成[sql, varsJson, rows, time.Now(), 1, 3]，总共6个参数，而INSERT语句只需要5个，因此报错。

通过db.Session(&gorm.Session{})创建新的会话后，新的DB实例不再携带原查询的上下文参数，此时执行Exec只会使用你传入的5个参数，就能正常插入日志了。

内容的提问来源于stack exchange，提问作者Anton Grünberg