diff --git a/core/db.go b/core/db.go index 8f16e848..1e25d007 100644 --- a/core/db.go +++ b/core/db.go @@ -12,7 +12,9 @@ import ( "reflect" "regexp" "sync" + "time" + "xorm.io/xorm/log" "xorm.io/xorm/names" ) @@ -81,6 +83,7 @@ type DB struct { Mapper names.Mapper reflectCache map[reflect.Type]*cacheStruct reflectCacheMutex sync.RWMutex + Logger log.ContextLogger } // Open opens a database @@ -120,7 +123,20 @@ func (db *DB) reflectNew(typ reflect.Type) reflect.Value { // QueryContext overwrites sql.DB.QueryContext func (db *DB) QueryContext(ctx context.Context, query string, args ...interface{}) (*Rows, error) { + start := time.Now() + db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: query, + Args: args, + }) rows, err := db.DB.QueryContext(ctx, query, args...) + db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: query, + Args: args, + ExecuteTime: time.Now().Sub(start), + Err: err, + }) if err != nil { if rows != nil { rows.Close() @@ -209,7 +225,7 @@ func (db *DB) ExecMapContext(ctx context.Context, query string, mp interface{}) if err != nil { return nil, err } - return db.DB.ExecContext(ctx, query, args...) + return db.ExecContext(ctx, query, args...) } func (db *DB) ExecMap(query string, mp interface{}) (sql.Result, error) { @@ -221,7 +237,25 @@ func (db *DB) ExecStructContext(ctx context.Context, query string, st interface{ if err != nil { return nil, err } - return db.DB.ExecContext(ctx, query, args...) + return db.ExecContext(ctx, query, args...) +} + +func (db *DB) ExecContext(ctx context.Context, query string, args ...interface{}) (sql.Result, error) { + start := time.Now() + db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: query, + Args: args, + }) + res, err := db.DB.ExecContext(ctx, query, args...) + db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: query, + Args: args, + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + return res, err } func (db *DB) ExecStruct(query string, st interface{}) (sql.Result, error) { diff --git a/dialects/dialect.go b/dialects/dialect.go index e9e512ee..4fbc4754 100644 --- a/dialects/dialect.go +++ b/dialects/dialect.go @@ -34,7 +34,7 @@ type URI struct { // a dialect is a driver's wrapper type Dialect interface { - SetLogger(logger log.Logger) + SetLogger(logger log.ContextLogger) Init(*core.DB, *URI, string, string) error URI() *URI DB() *core.DB @@ -92,7 +92,7 @@ type Base struct { dialect Dialect driverName string dataSourceName string - logger log.Logger + logger log.ContextLogger uri *URI } @@ -100,7 +100,7 @@ func (b *Base) DB() *core.DB { return b.db } -func (b *Base) SetLogger(logger log.Logger) { +func (b *Base) SetLogger(logger log.ContextLogger) { b.logger = logger } @@ -201,7 +201,6 @@ func (db *Base) DropTableSQL(tableName string) string { } func (db *Base) HasRecords(ctx context.Context, query string, args ...interface{}) (bool, error) { - db.LogSQL(query, args) rows, err := db.DB().QueryContext(ctx, query, args...) if err != nil { return false, err @@ -323,16 +322,6 @@ func (b *Base) ForUpdateSQL(query string) string { return query + " FOR UPDATE" } -func (b *Base) LogSQL(sql string, args []interface{}) { - if b.logger != nil && b.logger.IsShowSQL() { - if len(args) > 0 { - b.logger.Infof("[SQL] %v %v", sql, args) - } else { - b.logger.Infof("[SQL] %v", sql) - } - } -} - func (b *Base) SetParams(params map[string]string) { } diff --git a/dialects/mssql.go b/dialects/mssql.go index 83844f4e..9963fc4f 100644 --- a/dialects/mssql.go +++ b/dialects/mssql.go @@ -351,7 +351,6 @@ func (db *mssql) GetColumns(ctx context.Context, tableName string) ([]string, ma LEFT OUTER JOIN sys.indexes i ON ic.object_id = i.object_id AND ic.index_id = i.index_id where a.object_id=object_id('` + tableName + `')` - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -411,7 +410,6 @@ func (db *mssql) GetColumns(ctx context.Context, tableName string) ([]string, ma func (db *mssql) GetTables(ctx context.Context) ([]*schemas.Table, error) { args := []interface{}{} s := `select name from sysobjects where xtype ='U'` - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -446,7 +444,6 @@ INNER JOIN SYS.COLUMNS C ON IXS.OBJECT_ID=C.OBJECT_ID AND IXCS.COLUMN_ID=C.COLUMN_ID WHERE IXS.TYPE_DESC='NONCLUSTERED' and OBJECT_NAME(IXS.OBJECT_ID) =? ` - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { diff --git a/dialects/mysql.go b/dialects/mysql.go index 62fc6eb1..09384e89 100644 --- a/dialects/mysql.go +++ b/dialects/mysql.go @@ -319,7 +319,6 @@ func (db *mysql) GetColumns(ctx context.Context, tableName string) ([]string, ma args := []interface{}{db.uri.DBName, tableName} s := "SELECT `COLUMN_NAME`, `IS_NULLABLE`, `COLUMN_DEFAULT`, `COLUMN_TYPE`," + " `COLUMN_KEY`, `EXTRA`,`COLUMN_COMMENT` FROM `INFORMATION_SCHEMA`.`COLUMNS` WHERE `TABLE_SCHEMA` = ? AND `TABLE_NAME` = ?" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -430,7 +429,6 @@ func (db *mysql) GetTables(ctx context.Context) ([]*schemas.Table, error) { args := []interface{}{db.uri.DBName} s := "SELECT `TABLE_NAME`, `ENGINE`, `TABLE_ROWS`, `AUTO_INCREMENT`, `TABLE_COMMENT` from " + "`INFORMATION_SCHEMA`.`TABLES` WHERE `TABLE_SCHEMA`=? AND (`ENGINE`='MyISAM' OR `ENGINE` = 'InnoDB' OR `ENGINE` = 'TokuDB')" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -459,7 +457,6 @@ func (db *mysql) GetTables(ctx context.Context) ([]*schemas.Table, error) { func (db *mysql) GetIndexes(ctx context.Context, tableName string) (map[string]*schemas.Index, error) { args := []interface{}{db.uri.DBName, tableName} s := "SELECT `INDEX_NAME`, `NON_UNIQUE`, `COLUMN_NAME` FROM `INFORMATION_SCHEMA`.`STATISTICS` WHERE `TABLE_SCHEMA` = ? AND `TABLE_NAME` = ?" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { diff --git a/dialects/oracle.go b/dialects/oracle.go index 1247d7a4..3b9989d9 100644 --- a/dialects/oracle.go +++ b/dialects/oracle.go @@ -635,7 +635,6 @@ func (db *oracle) IsColumnExist(ctx context.Context, tableName, colName string) args := []interface{}{tableName, colName} query := "SELECT column_name FROM USER_TAB_COLUMNS WHERE table_name = :1" + " AND column_name = :2" - db.LogSQL(query, args) rows, err := db.DB().QueryContext(ctx, query, args...) if err != nil { @@ -653,7 +652,6 @@ func (db *oracle) GetColumns(ctx context.Context, tableName string) ([]string, m args := []interface{}{tableName} s := "SELECT column_name,data_default,data_type,data_length,data_precision,data_scale," + "nullable FROM USER_TAB_COLUMNS WHERE table_name = :1" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -750,7 +748,6 @@ func (db *oracle) GetColumns(ctx context.Context, tableName string) ([]string, m func (db *oracle) GetTables(ctx context.Context) ([]*schemas.Table, error) { args := []interface{}{} s := "SELECT table_name FROM user_tables" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -775,7 +772,6 @@ func (db *oracle) GetIndexes(ctx context.Context, tableName string) (map[string] args := []interface{}{tableName} s := "SELECT t.column_name,i.uniqueness,i.index_name FROM user_ind_columns t,user_indexes i " + "WHERE t.index_name = i.index_name and t.table_name = i.table_name and t.table_name =:1" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { diff --git a/dialects/postgres.go b/dialects/postgres.go index 94514e95..2e314812 100644 --- a/dialects/postgres.go +++ b/dialects/postgres.go @@ -943,7 +943,6 @@ func (db *postgres) IsColumnExist(ctx context.Context, tableName, colName string query = "SELECT column_name FROM INFORMATION_SCHEMA.COLUMNS WHERE table_name = $1" + " AND column_name = $2" } - db.LogSQL(query, args) rows, err := db.DB().QueryContext(ctx, query, args...) if err != nil { @@ -975,8 +974,6 @@ WHERE c.relkind = 'r'::char AND c.relname = $1%s AND f.attnum > 0 ORDER BY f.att } s = fmt.Sprintf(s, f) - db.LogSQL(s, args) - rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { return nil, nil, err @@ -1077,8 +1074,6 @@ func (db *postgres) GetTables(ctx context.Context) ([]*schemas.Table, error) { s = s + " WHERE schemaname = $1" } - db.LogSQL(s, args) - rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { return nil, err @@ -1117,7 +1112,6 @@ func (db *postgres) GetIndexes(ctx context.Context, tableName string) (map[strin args = append(args, db.uri.Schema) s = s + " AND schemaname=$2" } - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { diff --git a/dialects/sqlite3.go b/dialects/sqlite3.go index 5511468f..7dfa7fca 100644 --- a/dialects/sqlite3.go +++ b/dialects/sqlite3.go @@ -249,16 +249,10 @@ func (db *sqlite3) ForUpdateSQL(query string) string { return query } -/*func (db *sqlite3) ColumnCheckSql(tableName, colName string) (string, []interface{}) { - args := []interface{}{tableName} - sql := "SELECT name FROM sqlite_master WHERE type='table' and name = ? and ((sql like '%`" + colName + "`%') or (sql like '%[" + colName + "]%'))" - return sql, args -}*/ - func (db *sqlite3) IsColumnExist(ctx context.Context, tableName, colName string) (bool, error) { args := []interface{}{tableName} query := "SELECT name FROM sqlite_master WHERE type='table' and name = ? and ((sql like '%`" + colName + "`%') or (sql like '%[" + colName + "]%'))" - db.LogSQL(query, args) + rows, err := db.DB().QueryContext(ctx, query, args...) if err != nil { return false, err @@ -336,7 +330,7 @@ func parseString(colStr string) (*schemas.Column, error) { func (db *sqlite3) GetColumns(ctx context.Context, tableName string) ([]string, map[string]*schemas.Column, error) { args := []interface{}{tableName} s := "SELECT sql FROM sqlite_master WHERE type='table' and name = ?" - db.LogSQL(s, args) + rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { return nil, nil, err @@ -393,7 +387,6 @@ func (db *sqlite3) GetColumns(ctx context.Context, tableName string) ([]string, func (db *sqlite3) GetTables(ctx context.Context) ([]*schemas.Table, error) { args := []interface{}{} s := "SELECT name FROM sqlite_master WHERE type='table'" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { @@ -419,7 +412,6 @@ func (db *sqlite3) GetTables(ctx context.Context) ([]*schemas.Table, error) { func (db *sqlite3) GetIndexes(ctx context.Context, tableName string) (map[string]*schemas.Index, error) { args := []interface{}{tableName} s := "SELECT sql FROM sqlite_master WHERE type='index' and tbl_name = ?" - db.LogSQL(s, args) rows, err := db.DB().QueryContext(ctx, s, args...) if err != nil { diff --git a/engine.go b/engine.go index cf0126e9..12ef0fa9 100644 --- a/engine.go +++ b/engine.go @@ -37,7 +37,7 @@ type Engine struct { showSQL bool showExecTime bool - logger log.Logger + logger log.ContextLogger TZLocation *time.Location // The timezone of the application DatabaseTZ *time.Location // The timezone of the database @@ -84,15 +84,16 @@ func (engine *Engine) ShowExecTime(show ...bool) { } // Logger return the logger interface -func (engine *Engine) Logger() log.Logger { +func (engine *Engine) Logger() log.ContextLogger { return engine.logger } // SetLogger set the new logger -func (engine *Engine) SetLogger(logger log.Logger) { +func (engine *Engine) SetLogger(logger log.ContextLogger) { engine.logger = logger engine.showSQL = logger.IsShowSQL() engine.dialect.SetLogger(logger) + engine.db.Logger = logger } // SetLogLevel sets the logger level @@ -255,17 +256,6 @@ func (engine *Engine) Ping() error { return session.Ping() } -// logSQL save sql -func (engine *Engine) logSQL(sqlStr string, sqlArgs ...interface{}) { - if engine.showSQL && !engine.showExecTime { - if len(sqlArgs) > 0 { - engine.logger.Infof("[SQL] %v %#v", sqlStr, sqlArgs) - } else { - engine.logger.Infof("[SQL] %v", sqlStr) - } - } -} - // SQL method let's you manually write raw SQL and operate // For example: // @@ -763,7 +753,7 @@ func (engine *Engine) IsTableExist(beanOrTableName interface{}) (bool, error) { } // IDOf get id from one struct -func (engine *Engine) IDOf(bean interface{}) schemas.PK { +func (engine *Engine) IDOf(bean interface{}) (schemas.PK, error) { return engine.IDOfV(reflect.ValueOf(bean)) } @@ -773,13 +763,8 @@ func (engine *Engine) TableName(bean interface{}, includeSchema ...bool) string } // IDOfV get id from one value of struct -func (engine *Engine) IDOfV(rv reflect.Value) schemas.PK { - pk, err := engine.idOfV(rv) - if err != nil { - engine.logger.Error(err) - return nil - } - return pk +func (engine *Engine) IDOfV(rv reflect.Value) (schemas.PK, error) { + return engine.idOfV(rv) } func (engine *Engine) idOfV(rv reflect.Value) (schemas.PK, error) { @@ -1216,8 +1201,7 @@ func (engine *Engine) Import(r io.Reader) ([]sql.Result, error) { for scanner.Scan() { query := strings.Trim(scanner.Text(), " \t\n\r") if len(query) > 0 { - engine.logSQL(query) - result, err := engine.DB().Exec(query) + result, err := engine.DB().ExecContext(engine.defaultContext, query) results = append(results, result) if err != nil { return nil, err diff --git a/engine_group.go b/engine_group.go index 55159d55..9b18caa2 100644 --- a/engine_group.go +++ b/engine_group.go @@ -135,7 +135,7 @@ func (eg *EngineGroup) SetDefaultCacher(cacher caches.Cacher) { } // SetLogger set the new logger -func (eg *EngineGroup) SetLogger(logger log.Logger) { +func (eg *EngineGroup) SetLogger(logger log.ContextLogger) { eg.Engine.SetLogger(logger) for i := 0; i < len(eg.slaves); i++ { eg.slaves[i].SetLogger(logger) diff --git a/interface.go b/interface.go index e7894012..988b6d2d 100644 --- a/interface.go +++ b/interface.go @@ -98,7 +98,7 @@ type EngineInterface interface { SetConnMaxLifetime(time.Duration) SetColumnMapper(names.Mapper) SetDefaultCacher(caches.Cacher) - SetLogger(logger log.Logger) + SetLogger(logger log.ContextLogger) SetLogLevel(log.LogLevel) SetMapper(names.Mapper) SetMaxOpenConns(int) diff --git a/log/logger_context.go b/log/logger_context.go index b55b0670..d9f18682 100644 --- a/log/logger_context.go +++ b/log/logger_context.go @@ -6,27 +6,26 @@ package log import ( "context" - "fmt" "time" ) // LogContext represents a log context type LogContext struct { Ctx context.Context - LogLevel LogLevel - LogData string // log content or SQL + SQL string // log content or SQL Args []interface{} // if it's a SQL, it's the arguments - IsSQL bool ExecuteTime time.Duration + Err error // SQL executed error } // ContextLogger represents a logger interface with context type ContextLogger interface { - Debug(ctx LogContext) - Error(ctx LogContext) - Info(ctx LogContext) - Warn(ctx LogContext) - Before(context LogContext) + Debugf(format string, v ...interface{}) + Errorf(format string, v ...interface{}) + Infof(format string, v ...interface{}) + Warnf(format string, v ...interface{}) + BeforeSQL(context LogContext) + AfterSQL(context LogContext) Level() LogLevel SetLevel(l LogLevel) @@ -44,29 +43,40 @@ type LoggerAdapter struct { logger Logger } -func (l *LoggerAdapter) Before(ctx LogContext) {} - -func (l *LoggerAdapter) Debug(ctx LogContext) { - l.logger.Debug(ctx.LogData) +func NewLoggerAdapter(logger Logger) ContextLogger { + return &LoggerAdapter{ + logger: logger, + } } -func (l *LoggerAdapter) Error(ctx LogContext) { - l.logger.Error(ctx.LogData) -} +func (l *LoggerAdapter) BeforeSQL(ctx LogContext) {} -func (l *LoggerAdapter) Info(ctx LogContext) { - if !l.logger.IsShowSQL() && ctx.IsSQL { +func (l *LoggerAdapter) AfterSQL(ctx LogContext) { + if !l.logger.IsShowSQL() { return } - if ctx.IsSQL { - l.logger.Info(fmt.Sprintf("[SQL] %v %v", ctx.LogData, ctx.Args)) + + if ctx.ExecuteTime > 0 { + l.logger.Infof("[SQL] %v %v - %v", ctx.SQL, ctx.Args, ctx.ExecuteTime) } else { - l.logger.Info(ctx.LogData) + l.logger.Infof("[SQL] %v %v", ctx.SQL, ctx.Args) } } -func (l *LoggerAdapter) Warn(ctx LogContext) { - l.logger.Warn(ctx.LogData) +func (l *LoggerAdapter) Debugf(format string, v ...interface{}) { + l.logger.Debugf(format, v...) +} + +func (l *LoggerAdapter) Errorf(format string, v ...interface{}) { + l.logger.Errorf(format, v...) +} + +func (l *LoggerAdapter) Infof(format string, v ...interface{}) { + l.logger.Infof(format, v...) +} + +func (l *LoggerAdapter) Warnf(format string, v ...interface{}) { + l.logger.Warnf(format, v...) } func (l *LoggerAdapter) Level() LogLevel { diff --git a/session.go b/session.go index 92063882..95438d97 100644 --- a/session.go +++ b/session.go @@ -165,7 +165,7 @@ func (session *Session) After(closures func(interface{})) *Session { // Table can input a string or pointer to struct for special a table to operate. func (session *Session) Table(tableNameOrBean interface{}) *Session { if err := session.statement.SetTable(tableNameOrBean); err != nil { - session.engine.logger.Error(err) + session.statement.LastError = err } return session } @@ -447,7 +447,7 @@ func (session *Session) slice2Bean(scanResults []interface{}, fields []string, b fieldValue, err := session.getField(dataStruct, key, table, idx) if err != nil { if !strings.Contains(err.Error(), "is not valid") { - session.engine.logger.Warn(err) + session.engine.logger.Warnf("%v", err) } continue } @@ -650,7 +650,7 @@ func (session *Session) slice2Bean(scanResults []interface{}, fields []string, b hasAssigned = true t, err := session.byte2Time(col, d) if err != nil { - session.engine.logger.Error("byte2Time error:", err.Error()) + session.engine.logger.Errorf("byte2Time error: %v", err) hasAssigned = false } else { fieldValue.Set(reflect.ValueOf(t).Convert(fieldType)) @@ -659,7 +659,7 @@ func (session *Session) slice2Bean(scanResults []interface{}, fields []string, b hasAssigned = true t, err := session.str2Time(col, d) if err != nil { - session.engine.logger.Error("byte2Time error:", err.Error()) + session.engine.logger.Errorf("byte2Time error: %v", err) hasAssigned = false } else { fieldValue.Set(reflect.ValueOf(t).Convert(fieldType)) @@ -672,7 +672,7 @@ func (session *Session) slice2Bean(scanResults []interface{}, fields []string, b // !! 增加支持sql.Scanner接口的结构，如sql.NullString hasAssigned = true if err := nulVal.Scan(vv.Interface()); err != nil { - session.engine.logger.Error("sql.Sanner error:", err.Error()) + session.engine.logger.Errorf("sql.Sanner error: %v", err) hasAssigned = false } } else if col.SQLType.IsJson() { diff --git a/session_convert.go b/session_convert.go index 735aefa6..41ab75a9 100644 --- a/session_convert.go +++ b/session_convert.go @@ -111,7 +111,6 @@ func (session *Session) bytes2Value(col *schemas.Column, fieldValue *reflect.Val if len(data) > 0 { err := json.DefaultJSONHandler.Unmarshal(data, x.Interface()) if err != nil { - session.engine.logger.Error(err) return err } fieldValue.Set(x.Elem()) @@ -125,7 +124,6 @@ func (session *Session) bytes2Value(col *schemas.Column, fieldValue *reflect.Val if len(data) > 0 { err := json.DefaultJSONHandler.Unmarshal(data, x.Interface()) if err != nil { - session.engine.logger.Error(err) return err } fieldValue.Set(x.Elem()) @@ -138,7 +136,6 @@ func (session *Session) bytes2Value(col *schemas.Column, fieldValue *reflect.Val if len(data) > 0 { err := json.DefaultJSONHandler.Unmarshal(data, x.Interface()) if err != nil { - session.engine.logger.Error(err) return err } fieldValue.Set(x.Elem()) @@ -267,7 +264,6 @@ func (session *Session) bytes2Value(col *schemas.Column, fieldValue *reflect.Val if len(data) > 0 { err := json.DefaultJSONHandler.Unmarshal(data, &x) if err != nil { - session.engine.logger.Error(err) return err } fieldValue.Set(reflect.ValueOf(&x).Convert(fieldType)) @@ -278,7 +274,6 @@ func (session *Session) bytes2Value(col *schemas.Column, fieldValue *reflect.Val if len(data) > 0 { err := json.DefaultJSONHandler.Unmarshal(data, &x) if err != nil { - session.engine.logger.Error(err) return err } fieldValue.Set(reflect.ValueOf(&x).Convert(fieldType)) @@ -570,7 +565,7 @@ func (session *Session) value2Interface(col *schemas.Column, fieldValue reflect. if fieldValue.IsNil() { return nil, nil } else if !fieldValue.IsValid() { - session.engine.logger.Warn("the field[", col.FieldName, "] is invalid") + session.engine.logger.Warnf("the field [%s] is invalid", col.FieldName) return nil, nil } else { // !nashtsai! deference pointer type to instance type @@ -618,14 +613,12 @@ func (session *Session) value2Interface(col *schemas.Column, fieldValue reflect. if col.SQLType.IsText() { bytes, err := json.DefaultJSONHandler.Marshal(fieldValue.Interface()) if err != nil { - session.engine.logger.Error(err) return 0, err } return string(bytes), nil } else if col.SQLType.IsBlob() { bytes, err := json.DefaultJSONHandler.Marshal(fieldValue.Interface()) if err != nil { - session.engine.logger.Error(err) return 0, err } return bytes, nil @@ -634,7 +627,6 @@ func (session *Session) value2Interface(col *schemas.Column, fieldValue reflect. case reflect.Complex64, reflect.Complex128: bytes, err := json.DefaultJSONHandler.Marshal(fieldValue.Interface()) if err != nil { - session.engine.logger.Error(err) return 0, err } return string(bytes), nil @@ -646,7 +638,6 @@ func (session *Session) value2Interface(col *schemas.Column, fieldValue reflect. if col.SQLType.IsText() { bytes, err := json.DefaultJSONHandler.Marshal(fieldValue.Interface()) if err != nil { - session.engine.logger.Error(err) return 0, err } return string(bytes), nil @@ -659,7 +650,6 @@ func (session *Session) value2Interface(col *schemas.Column, fieldValue reflect. } else { bytes, err = json.DefaultJSONHandler.Marshal(fieldValue.Interface()) if err != nil { - session.engine.logger.Error(err) return 0, err } } diff --git a/session_delete.go b/session_delete.go index f21151e1..04200035 100644 --- a/session_delete.go +++ b/session_delete.go @@ -62,14 +62,14 @@ func (session *Session) cacheDelete(table *schemas.Table, tableName, sqlStr stri } for _, id := range ids { - session.engine.logger.Debug("[cacheDelete] delete cache obj:", tableName, id) + session.engine.logger.Debugf("[cache] delete cache obj: %v, %v", tableName, id) sid, err := id.ToString() if err != nil { return err } cacher.DelBean(tableName, sid) } - session.engine.logger.Debug("[cacheDelete] clear cache table:", tableName) + session.engine.logger.Debugf("[cache] clear cache table: %v", tableName) cacher.ClearIds(tableName) return nil } diff --git a/session_find.go b/session_find.go index a3ba2c82..97273428 100644 --- a/session_find.go +++ b/session_find.go @@ -141,7 +141,7 @@ func (session *Session) find(rowsSlicePtr interface{}, condiBean ...interface{}) return err } err = nil // !nashtsai! reset err to nil for ErrCacheFailed - session.engine.logger.Warn("Cache Find Failed") + session.engine.logger.Warnf("Cache Find Failed") } } @@ -307,7 +307,7 @@ func (session *Session) cacheFind(t reflect.Type, sqlStr string, rowsSlicePtr in for rows.Next() { i++ if i > 500 { - session.engine.logger.Debug("[cacheFind] ids length > 500, no cache") + session.engine.logger.Debugf("[cacheFind] ids length > 500, no cache") return ErrCacheFailed } var res = make([]string, len(table.PrimaryKeys)) @@ -326,13 +326,13 @@ func (session *Session) cacheFind(t reflect.Type, sqlStr string, rowsSlicePtr in ids = append(ids, pk) } - session.engine.logger.Debug("[cacheFind] cache sql:", ids, tableName, sqlStr, newsql, args) + session.engine.logger.Debugf("[cache] cache sql: %v, %v, %v, %v, %v", ids, tableName, sqlStr, newsql, args) err = caches.PutCacheSql(cacher, ids, tableName, newsql, args) if err != nil { return err } } else { - session.engine.logger.Debug("[cacheFind] cache hit sql:", tableName, sqlStr, newsql, args) + session.engine.logger.Debugf("[cache] cache hit sql: %v, %v, %v, %v", tableName, sqlStr, newsql, args) } sliceValue := reflect.Indirect(reflect.ValueOf(rowsSlicePtr)) @@ -365,16 +365,20 @@ func (session *Session) cacheFind(t reflect.Type, sqlStr string, rowsSlicePtr in ides = append(ides, id) ididxes[sid] = idx } else { - session.engine.logger.Debug("[cacheFind] cache hit bean:", tableName, id, bean) + session.engine.logger.Debugf("[cache] cache hit bean: %v, %v, %v", tableName, id, bean) + + pk, err := session.engine.IDOf(bean) + if err != nil { + return err + } - pk := session.engine.IDOf(bean) xid, err := pk.ToString() if err != nil { return err } if sid != xid { - session.engine.logger.Error("[cacheFind] error cache", xid, sid, bean) + session.engine.logger.Errorf("[cache] error cache: %v, %v, %v", xid, sid, bean) return ErrCacheFailed } temps[idx] = bean @@ -424,7 +428,7 @@ func (session *Session) cacheFind(t reflect.Type, sqlStr string, rowsSlicePtr in bean := rv.Interface() temps[ididxes[sid]] = bean - session.engine.logger.Debug("[cacheFind] cache bean:", tableName, id, bean, temps) + session.engine.logger.Debugf("[cache] cache bean: %v, %v, %v, %v", tableName, id, bean, temps) cacher.PutBean(tableName, sid, bean) } } @@ -432,7 +436,7 @@ func (session *Session) cacheFind(t reflect.Type, sqlStr string, rowsSlicePtr in for j := 0; j < len(temps); j++ { bean := temps[j] if bean == nil { - session.engine.logger.Warn("[cacheFind] cache no hit:", tableName, ids[j], temps) + session.engine.logger.Warnf("[cache] cache no hit: %v, %v, %v", tableName, ids[j], temps) // return errors.New("cache error") // !nashtsai! no need to return error, but continue instead continue } diff --git a/session_get.go b/session_get.go index f0fc016b..c468b440 100644 --- a/session_get.go +++ b/session_get.go @@ -79,7 +79,7 @@ func (session *Session) get(bean interface{}) (bool, error) { if context != nil { res := context.Get(fmt.Sprintf("%v-%v", sqlStr, args)) if res != nil { - session.engine.logger.Debug("hit context cache", sqlStr) + session.engine.logger.Debugf("hit context cache: %s", sqlStr) structValue := reflect.Indirect(reflect.ValueOf(bean)) structValue.Set(reflect.Indirect(reflect.ValueOf(res))) @@ -283,7 +283,7 @@ func (session *Session) cacheGet(bean interface{}, sqlStr string, args ...interf tableName := session.statement.TableName() cacher := session.engine.cacherMgr.GetCacher(tableName) - session.engine.logger.Debug("[cache] Get SQL:", newsql, args) + session.engine.logger.Debugf("[cache] Get SQL: %s, %v", newsql, args) table := session.statement.RefTable ids, err := caches.GetCacheSql(cacher, tableName, newsql, args) if err != nil { @@ -319,19 +319,19 @@ func (session *Session) cacheGet(bean interface{}, sqlStr string, args ...interf } ids = []schemas.PK{pk} - session.engine.logger.Debug("[cache] cache ids:", newsql, ids) + session.engine.logger.Debugf("[cache] cache ids: %s, %v", newsql, ids) err = caches.PutCacheSql(cacher, ids, tableName, newsql, args) if err != nil { return false, err } } else { - session.engine.logger.Debug("[cache] cache hit:", newsql, ids) + session.engine.logger.Debugf("[cache] cache hit: %s, %v", newsql, ids) } if len(ids) > 0 { structValue := reflect.Indirect(reflect.ValueOf(bean)) id := ids[0] - session.engine.logger.Debug("[cache] get bean:", tableName, id) + session.engine.logger.Debugf("[cache] get bean: %s, %v", tableName, id) sid, err := id.ToString() if err != nil { return false, err @@ -344,10 +344,10 @@ func (session *Session) cacheGet(bean interface{}, sqlStr string, args ...interf return has, err } - session.engine.logger.Debug("[cache] cache bean:", tableName, id, cacheBean) + session.engine.logger.Debugf("[cache] cache bean: %s, %v, %v", tableName, id, cacheBean) cacher.PutBean(tableName, sid, cacheBean) } else { - session.engine.logger.Debug("[cache] cache hit:", tableName, id, cacheBean) + session.engine.logger.Debugf("[cache] cache hit: %s, %v, %v", tableName, id, cacheBean) has = true } structValue.Set(reflect.Indirect(reflect.ValueOf(cacheBean))) diff --git a/session_insert.go b/session_insert.go index 2206ad05..4662e25a 100644 --- a/session_insert.go +++ b/session_insert.go @@ -485,7 +485,7 @@ func (session *Session) innerInsert(bean interface{}) (int64, error) { if table.Version != "" && session.statement.CheckVersion { verValue, err := table.VersionColumn().ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } else if verValue.IsValid() && verValue.CanSet() { session.incrVersionFieldValue(verValue) } @@ -503,7 +503,7 @@ func (session *Session) innerInsert(bean interface{}) (int64, error) { aiValue, err := table.AutoIncrColumn().ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } if aiValue == nil || !aiValue.IsValid() || !aiValue.CanSet() { @@ -526,7 +526,7 @@ func (session *Session) innerInsert(bean interface{}) (int64, error) { if table.Version != "" && session.statement.CheckVersion { verValue, err := table.VersionColumn().ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } else if verValue.IsValid() && verValue.CanSet() { session.incrVersionFieldValue(verValue) } @@ -544,7 +544,7 @@ func (session *Session) innerInsert(bean interface{}) (int64, error) { aiValue, err := table.AutoIncrColumn().ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } if aiValue == nil || !aiValue.IsValid() || !aiValue.CanSet() { @@ -567,7 +567,7 @@ func (session *Session) innerInsert(bean interface{}) (int64, error) { if table.Version != "" && session.statement.CheckVersion { verValue, err := table.VersionColumn().ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } else if verValue.IsValid() && verValue.CanSet() { session.incrVersionFieldValue(verValue) } @@ -585,7 +585,7 @@ func (session *Session) innerInsert(bean interface{}) (int64, error) { aiValue, err := table.AutoIncrColumn().ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } if aiValue == nil || !aiValue.IsValid() || !aiValue.CanSet() { @@ -617,7 +617,7 @@ func (session *Session) cacheInsert(table string) error { if cacher == nil { return nil } - session.engine.logger.Debug("[cache] clear sql:", table) + session.engine.logger.Debugf("[cache] clear sql: %v", table) cacher.ClearIds(table) return nil } diff --git a/session_update.go b/session_update.go index bb53c3a1..551b8167 100644 --- a/session_update.go +++ b/session_update.go @@ -30,7 +30,7 @@ func (session *Session) cacheUpdate(table *schemas.Table, tableName, sqlStr stri for _, filter := range session.engine.dialect.Filters() { newsql = filter.Do(newsql) } - session.engine.logger.Debug("[cacheUpdate] new sql", oldhead, newsql) + session.engine.logger.Debugf("[cache] new sql: %v, %v", oldhead, newsql) var nStart int if len(args) > 0 { @@ -43,7 +43,7 @@ func (session *Session) cacheUpdate(table *schemas.Table, tableName, sqlStr stri } cacher := session.engine.GetCacher(tableName) - session.engine.logger.Debug("[cacheUpdate] get cache sql", newsql, args[nStart:]) + session.engine.logger.Debugf("[cache] get cache sql: %v, %v", newsql, args[nStart:]) ids, err := caches.GetCacheSql(cacher, tableName, newsql, args[nStart:]) if err != nil { rows, err := session.NoCache().queryRows(newsql, args[nStart:]...) @@ -76,7 +76,7 @@ func (session *Session) cacheUpdate(table *schemas.Table, tableName, sqlStr stri ids = append(ids, pk) } - session.engine.logger.Debug("[cacheUpdate] find updated id", ids) + session.engine.logger.Debugf("[cache] find updated id: %v", ids) } /*else { session.engine.LogDebug("[xorm:cacheUpdate] del cached sql:", tableName, newsql, args) cacher.DelIds(tableName, genSqlKey(newsql, args)) @@ -109,9 +109,9 @@ func (session *Session) cacheUpdate(table *schemas.Table, tableName, sqlStr stri if col := table.GetColumn(colName); col != nil { fieldValue, err := col.ValueOf(bean) if err != nil { - session.engine.logger.Error(err) + session.engine.logger.Errorf("%v", err) } else { - session.engine.logger.Debug("[cacheUpdate] set bean field", bean, colName, fieldValue.Interface()) + session.engine.logger.Debugf("[cache] set bean field: %v, %v, %v", bean, colName, fieldValue.Interface()) if col.IsVersion && session.statement.CheckVersion { session.incrVersionFieldValue(fieldValue) } else { @@ -119,16 +119,16 @@ func (session *Session) cacheUpdate(table *schemas.Table, tableName, sqlStr stri } } } else { - session.engine.logger.Errorf("[cacheUpdate] ERROR: column %v is not table %v's", + session.engine.logger.Errorf("[cache] ERROR: column %v is not table %v's", colName, table.Name) } } - session.engine.logger.Debug("[cacheUpdate] update cache", tableName, id, bean) + session.engine.logger.Debugf("[cache] update cache: %v, %v, %v", tableName, id, bean) cacher.PutBean(tableName, sid, bean) } } - session.engine.logger.Debug("[cacheUpdate] clear cached table sql:", tableName) + session.engine.logger.Debugf("[cache] clear cached table sql: %v", tableName) cacher.ClearIds(tableName) return nil } @@ -414,7 +414,7 @@ func (session *Session) Update(bean interface{}, condiBean ...interface{}) (int6 if cacher := session.engine.GetCacher(tableName); cacher != nil && session.statement.UseCache { // session.cacheUpdate(table, tableName, sqlStr, args...) - session.engine.logger.Debug("[cacheUpdate] clear table ", tableName) + session.engine.logger.Debugf("[cache] clear table: %v", tableName) cacher.ClearIds(tableName) cacher.ClearBeans(tableName) } @@ -425,7 +425,7 @@ func (session *Session) Update(bean interface{}, condiBean ...interface{}) (int6 closure(bean) } if processor, ok := interface{}(bean).(AfterUpdateProcessor); ok { - session.engine.logger.Debug("[event]", tableName, " has after update processor") + session.engine.logger.Debugf("[event] %v has after update processor", tableName) processor.AfterUpdate() } } else { diff --git a/xorm.go b/xorm.go index 2946b7c9..724a37cb 100644 --- a/xorm.go +++ b/xorm.go @@ -80,7 +80,7 @@ func NewEngine(driverName string, dataSourceName string) (*Engine, error) { logger := log.NewSimpleLogger(os.Stdout) logger.SetLevel(log.LOG_INFO) - engine.SetLogger(logger) + engine.SetLogger(log.NewLoggerAdapter(logger)) runtime.SetFinalizer(engine, close)