Your Question
I want to track every query to the database (MySQL). This is the init:
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)
}
This is my user struct
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"`
}
This the method for searching:
func (u *User) FindFirst() *User {
db.DBEnv.Db.First(u)
return u
}
And this is the call:
user3 := (*user.User).FindFirst(&user.User{ID: 3})
GORM makes the following query:
SELECT * FROM `users` WHERE `users`.`deleted_at` IS NULL AND `users`.`id` = ? ORDER BY `users`.`id` LIMIT 1
And in the query logger it makes:
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')
Why is GORM injecting the searched ID as an additional parameter into the db.Exec funtion? This causes the following error
sql: expected 5 arguments, got 6
Do I miss something out, or is this a bug?
The document you expected this should be explained
-
Expected answer
-
Comment From: ivila
@agruenberg GORM is not injecting the search ID into values, you are appending 5 values into the old search ID values. You should not use the db instance of the setQueryLogger function parameter, you should use DBEnv.Db instead, try changing your codes to the following:
// 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)
}
// do not use the db parameter to execute a new query, it's not stateless, it has scope values of your current query.
//db.Exec("INSERT INTO `query_logs` (`sql`,`parameters`, `rows_affected`, `executed_at`, `executed_by`) VALUES (?, ?, ?, ?, ?)", sql, varsJson, rows, time.Now(), 1)
DBEnv.Db.Exec("INSERT INTO `query_logs` (`sql`,`parameters`, `rows_affected`, `executed_at`, `executed_by`) VALUES (?, ?, ?, ?, ?)", sql, varsJson, rows, time.Now(), 1)
}
Moreover, after reading your codes, I see you are developing a plugin to add query log into your database, and I suggest is you should do it by writing a custom logger, it will be more clearer, see the official Logger(https://github.com/go-gorm/gorm/blob/master/logger/logger.go) for example, add your logic in the Trace method.
Comment From: agruenberg
Thank you very much, your advise to use DBEnv instead of db helped and it runs perfect. But because of curiosity, can you explain me why this happens with db?
@Logger: Yes, this is the next step.
Comment From: ivila
Thank you very much, your advise to use
DBEnvinstead ofdbhelped and it runs perfect. But because of curiosity, can you explain me why this happens withdb? @logger: Yes, this is the next step.
A gorm.DB instance is both a connection holder and a sql builder, and it copies on write. When you get a gorm.DB instance by gorm.Open (your DBEnv.Db), it is a clean sql builder with no extra values inside. When you call method like Where, First, etc. It copies and return a new instance(the db argument you are using in the setQueryLogger method) with extra values about your query.
Just like the following:
// DBEnv.Db is a clear fresh db instance
DBEnv.Db, _ := gorm.Open(...)
// dbInstance2 is a query builder with Where condition inside
// and the db argument of your setQueryLoggeris the dbInstance2, not the DBEnv.Db.
dbInstance2 := DBEnv.Db.First(u)
// and here is why you get extra values
// you are calling Exec method with a dirty sql builder, just like the following
dbInstance3 := dbInstance2.Exec(.....)
// and what we change is to use a clean sql builder
dbInstance4 := DBEnv.Db.Exec(....)
you may learn something after reading the following: 1) the getInstance method of gorm.DB, see the logic of clone: https://github.com/go-gorm/gorm/blob/418ee3fc1939d87a05bbb8ac6d7c7223e2c4571f/gorm.go#L398 2) the First method of gorm.DB, there is a Statement Field: https://github.com/go-gorm/gorm/blob/418ee3fc1939d87a05bbb8ac6d7c7223e2c4571f/finisher_api.go#L118 3) the Statement struct, the SQL and Vars fields: https://github.com/go-gorm/gorm/blob/418ee3fc1939d87a05bbb8ac6d7c7223e2c4571f/statement.go#L44
Comment From: github-actions[bot]
This issue has been automatically marked as stale because it has been open 360 days with no activity. Remove stale label or comment or this will be closed in 180 days