log context

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) {

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) {
 }
 

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 {

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 {

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 {

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 {

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 {

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 {
+func (engine *Engine) IDOfV(rv reflect.Value) (schemas.PK, error) {
-	pk, err := engine.idOfV(rv)
+	return engine.idOfV(rv)
-	if err != nil {
-		engine.logger.Error(err)
-		return nil
-	}
-	return pk
 }
 
 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().ExecContext(engine.defaultContext, query)
-			result, err := engine.DB().Exec(query)
 			results = append(results, result)
 			if err != nil {
 				return nil, err

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)

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)

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
+	SQL         string        // log content or SQL
-	LogData     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)
+	Debugf(format string, v ...interface{})
-	Error(ctx LogContext)
+	Errorf(format string, v ...interface{})
-	Info(ctx LogContext)
+	Infof(format string, v ...interface{})
-	Warn(ctx LogContext)
+	Warnf(format string, v ...interface{})
-	Before(context LogContext)
+	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 NewLoggerAdapter(logger Logger) ContextLogger {
-
+	return &LoggerAdapter{
-func (l *LoggerAdapter) Debug(ctx LogContext) {
+		logger: logger,
-	l.logger.Debug(ctx.LogData)
+	}
 }
 
-func (l *LoggerAdapter) Error(ctx LogContext) {
+func (l *LoggerAdapter) BeforeSQL(ctx LogContext) {}
-	l.logger.Error(ctx.LogData)
-}
 
-func (l *LoggerAdapter) Info(ctx LogContext) {
+func (l *LoggerAdapter) AfterSQL(ctx LogContext) {
-	if !l.logger.IsShowSQL() && ctx.IsSQL {
+	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) {
+func (l *LoggerAdapter) Debugf(format string, v ...interface{}) {
-	l.logger.Warn(ctx.LogData)
+	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 {

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
 				// !<winxxp>! 增加支持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() {

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
 				}
 			}

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
 }

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
 		}

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)))

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
 }

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 {

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)