From daf3766a22ecfd2733763752b13e54b53e360d6f Mon Sep 17 00:00:00 2001 From: Pavel Shevaev Date: Wed, 2 Nov 2022 17:55:53 +0300 Subject: [PATCH] Starting to migrate to unified logger --- .gitignore | 1 + db.go | 9 ++-- db_test.go | 127 +++++++++++++---------------------------------------- go.mod | 3 +- go.sum | 5 +++ logger.go | 48 +++++++++----------- 6 files changed, 65 insertions(+), 128 deletions(-) create mode 100644 .gitignore diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..6e92f57 --- /dev/null +++ b/.gitignore @@ -0,0 +1 @@ +tags diff --git a/db.go b/db.go index c18d6ba..9068cec 100644 --- a/db.go +++ b/db.go @@ -5,10 +5,11 @@ import ( "reflect" "time" - "git.bit5.ru/backend/colog" "git.bit5.ru/backend/dbr" "git.bit5.ru/backend/errors" "git.bit5.ru/backend/mysql" + + "github.com/go-logr/logr" ) type Settings struct { @@ -34,7 +35,7 @@ func (p *Pool) Close() { } type DBC struct { - Logger *colog.CoLog + Logger logr.Logger P *Pool //NOTE: it's not a 'connection', it embeds sql.Pool (dbr uses strange names for entities) con *dbr.Connection @@ -71,9 +72,9 @@ func OpenPool(s Settings) *Pool { return &Pool{DB: sqlDb, S: s} } -func GetDBC(p *Pool, logger *colog.CoLog) *DBC { +func GetDBC(p *Pool, logger logr.Logger) *DBC { - logger = logger.Clone().AddPrefix("[" + p.S.Prefix + "] ") + logger = logger.WithValues("db", p.S.Prefix) con := dbr.NewConnection(p.DB, nil) sess := con.NewSession(&EventReceiver{logger: logger, s: p.S}) diff --git a/db_test.go b/db_test.go index bd97cee..0634efa 100644 --- a/db_test.go +++ b/db_test.go @@ -1,17 +1,19 @@ package db_test import ( + "log" "os" "testing" - "git.bit5.ru/backend/colog" "git.bit5.ru/backend/db" "git.bit5.ru/backend/errors" - "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/go-logr/stdr" ) -var logger = colog.NewCoLog(os.Stderr, "", 0) +var logger = stdr.New(log.New(os.Stdout, "", log.Lshortfile)) func getSettings() db.Settings { //TODO: use ENV settings as well @@ -33,8 +35,8 @@ func TestDefaultClientCharsetAndCollation(t *testing.T) { var result = make(map[string]string) - characterSets, err := dbc.DB().Query("show variables where Variable_name in ('character_set_client', 'character_set_connection', 'character_set_results');") - assert.Nil(t, err) + characterSets, err := dbc.DB().Query("SHOW VARIABLES WHERE Variable_name in ('character_set_client', 'character_set_connection', 'character_set_results');") + require.Nil(t, err) for characterSets.Next() { @@ -47,7 +49,7 @@ func TestDefaultClientCharsetAndCollation(t *testing.T) { } collations, err := dbc.DB().Query("show variables where Variable_name = 'collation_connection';") - assert.Nil(t, err) + require.Nil(t, err) for collations.Next() { @@ -76,7 +78,7 @@ func TestClientCharsetAndCollation(t *testing.T) { dbLatin1 := db.GetDBC(pool, logger) characterSets, err := dbLatin1.DB().Query("show variables where Variable_name in ('character_set_client', 'character_set_connection', 'character_set_results');") - assert.Nil(t, err) + require.Nil(t, err) for characterSets.Next() { var variableName string @@ -88,7 +90,7 @@ func TestClientCharsetAndCollation(t *testing.T) { } collations, err := dbLatin1.DB().Query("show variables where Variable_name = 'collation_connection';") - assert.Nil(t, err) + require.Nil(t, err) for collations.Next() { @@ -113,9 +115,9 @@ func createFooTable(t *testing.T) { defer p.Close() _, err := dbc.DB().Exec("DROP TABLE IF EXISTS foo") - assert.Nil(t, err) + require.Nil(t, err) _, err = dbc.DB().Exec("CREATE TABLE IF NOT EXISTS foo(id int not null)") - assert.Nil(t, err) + require.Nil(t, err) } func TestTransactionCommit(t *testing.T) { @@ -125,7 +127,7 @@ func TestTransactionCommit(t *testing.T) { dbc := getDBC(p) defer p.Close() - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(1),(2)").Exec() //let's try a fresh connection @@ -148,7 +150,7 @@ func TestTransactionCommitNestedAllOk(t *testing.T) { dbc := getDBC(p) defer p.Close() //begin 1 - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(1),(2)").Exec() //let's try a fresh connection @@ -156,7 +158,7 @@ func TestTransactionCommitNestedAllOk(t *testing.T) { assert.EqualValues(t, 0, countFoos(t, dbc1)) //begin 2 - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(3)").Exec() //commit 2 dbc.Commit() @@ -182,7 +184,7 @@ func TestTransactionCommitNestedRollback(t *testing.T) { dbc := getDBC(p) defer p.Close() //begin 1 - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(1),(2)").Exec() //let's try a fresh connection @@ -190,7 +192,7 @@ func TestTransactionCommitNestedRollback(t *testing.T) { assert.EqualValues(t, 0, countFoos(t, dbc1)) //begin 2 - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(3)").Exec() //rollback 2 dbc.Rollback() @@ -283,7 +285,7 @@ func TestTransaction(t *testing.T) { dbc := getDBC(p) defer p.Close() - assert.Nil(t, dbc.Transaction(func(dbs *db.DBC) error { + require.Nil(t, dbc.Transaction(func(dbs *db.DBC) error { dbs.UpdateBySQL("INSERT INTO foo(id) VALUES(1),(2)").Exec() //let's try a fresh connection @@ -350,7 +352,7 @@ func TestTransactionRollbackOnPanic(t *testing.T) { func countFoos(t *testing.T, dbc *db.DBC) int { var res int err := dbc.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) return res } @@ -360,23 +362,23 @@ func TestTransactionRollback(t *testing.T) { p := getPool() dbc := getDBC(p) defer p.Close() - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) { _, err := dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(1),(2)").Exec() - assert.Nil(t, err) + require.Nil(t, err) } var res int { err := dbc.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) assert.EqualValues(t, 2, res) } dbc.Rollback() { err := dbc.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) assert.EqualValues(t, 0, res) } @@ -384,7 +386,7 @@ func TestTransactionRollback(t *testing.T) { dbc2 := getDBC(p) { err := dbc2.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) assert.EqualValues(t, 0, res) } } @@ -396,24 +398,24 @@ func TestTransactionNestedRollback(t *testing.T) { dbc := getDBC(p) defer p.Close() //begin 1 - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) { _, err := dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(1)").Exec() - assert.Nil(t, err) + require.Nil(t, err) } var res int { err := dbc.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) assert.EqualValues(t, 1, res) } //begin 2 - assert.Nil(t, dbc.Begin()) + require.Nil(t, dbc.Begin()) { _, err := dbc.UpdateBySQL("INSERT INTO foo(id) VALUES(1)").Exec() - assert.Nil(t, err) + require.Nil(t, err) } //no real rollback happens here since we are in a 'bigger' transaction @@ -421,7 +423,7 @@ func TestTransactionNestedRollback(t *testing.T) { dbc.Rollback() { err := dbc.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) assert.EqualValues(t, 2, res) } @@ -430,75 +432,8 @@ func TestTransactionNestedRollback(t *testing.T) { { err := dbc.SelectBySQL("SELECT COUNT(id) FROM foo").LoadValue(&res) - assert.Nil(t, err) + require.Nil(t, err) assert.EqualValues(t, 0, res) } } - -//func makePlayers(t *testing.T, env *env.Env, amount int) []uint32 { -// var players []uint32 -// mainDb := env.MainDb() -// -// for i := 0; i < amount; i++ { -// shardPlayer, err := dbshrd.CreateShardPlayer(env.Settings.DB_SHARDS, mainDb, 1) -// require.NoError(t, err) -// players = append(players, shardPlayer.Id) -// } -// -// //Note: There is only one test shard db, so the shard id = 1 for all players -// shardDb, err := dbshrd.GetShardDb(env.Logger, env.Settings.DB_SHARDS, 1) -// require.NoError(t, err) -// require.NotNil(t, shardDb) -// defer shardDb.Close() -// -// for i := 0; i < len(players); i++ { -// player := autogen.NewDataPlayer() -// player.Id = players[i] -// err = dbmeta.SaveRow(shardDb, player) -// require.NoError(t, err) -// } -// -// return players -//} - -//func TestSelectBySQLWithChunkedIN(t *testing.T) { -// env := tests.NewEnvCleanStorage() -// defer env.Close() -// -// //Note: There is only one test shard db, so the shard id = 1 for all players -// shardDb, err := dbshrd.GetShardDb(env.Logger, env.Settings.DB_SHARDS, 1) -// require.NoError(t, err) -// require.NotNil(t, shardDb) -// defer shardDb.Close() -// -// var playersAmount = 100 -// var playerIds []uint32 -// playerIds = makePlayers(t, env, playersAmount) -// -// for chunkSizeForIN := 1; chunkSizeForIN <= 101; chunkSizeForIN++ { -// var totalIds []uint32 -// fullChunksAmount := playersAmount / chunkSizeForIN -// modulo := playersAmount % chunkSizeForIN -// sql := "SELECT id FROM player WHERE 1 = ? AND id IN ? AND 2 = ?" -// builders := shardDb.SelectBySQLWithChunkedIN(sql, chunkSizeForIN, 1, playerIds, 2) -// -// require.Len(t, builders, fullChunksAmount+util.BoolToInt(modulo > 0)) -// -// for queryIndex, builder := range builders { -// var queryIds []uint32 -// _, err := builder.LoadValues(&queryIds) -// require.NoError(t, err) -// require.NotNil(t, queryIds) -// totalIds = append(totalIds, queryIds...) -// -// if queryIndex < fullChunksAmount { -// require.Len(t, queryIds, chunkSizeForIN) -// } else { -// require.Len(t, queryIds, modulo) -// } -// } -// -// require.Len(t, totalIds, playersAmount) -// } -//} diff --git a/go.mod b/go.mod index 8b20b0a..313b34a 100644 --- a/go.mod +++ b/go.mod @@ -3,10 +3,11 @@ module git.bit5.ru/backend/db go 1.13 require ( - git.bit5.ru/backend/colog v1.0.0 git.bit5.ru/backend/dbr v1.2.0 git.bit5.ru/backend/errors v1.0.0 git.bit5.ru/backend/mysql v1.0.0 git.bit5.ru/backend/res_tracker v1.1.1 + github.com/go-logr/logr v1.2.3 + github.com/go-logr/stdr v1.2.2 // indirect github.com/stretchr/testify v1.8.1 ) diff --git a/go.sum b/go.sum index 5712e1d..c974866 100644 --- a/go.sum +++ b/go.sum @@ -13,6 +13,11 @@ git.bit5.ru/backend/res_tracker v1.1.1/go.mod h1:ffjnItxqkGc6rxOK9XgrQDirGhmIBwo github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0= +github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/go-sql-driver/mysql v1.4.1 h1:g24URVg0OFbNUTx9qqY1IRZ9D9z3iPyi5zKhQZpNwpA= github.com/go-sql-driver/mysql v1.4.1/go.mod h1:zAC/RDZ24gD3HViQzih4MyKcchzm+sOG5ZlKdlhCg5w= github.com/golang/protobuf v1.3.1/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= diff --git a/logger.go b/logger.go index 1c45d2b..dfa24d9 100644 --- a/logger.go +++ b/logger.go @@ -3,28 +3,24 @@ package db import ( "strings" - "git.bit5.ru/backend/colog" + "github.com/go-logr/logr" ) // EventReceiver logs db stuff if neccessary type EventReceiver struct { - logger *colog.CoLog + logger logr.Logger s Settings } // Event receives a simple notification when various events occur func (n *EventReceiver) Event(eventName string) { - if n.logger != nil { - n.logger.Output(colog.LDebug, 5, eventName) - } + n.logger.WithCallDepth(5).V(1).Info(eventName) } // EventKv receives a notification when various events occur along with // optional key/value data func (n *EventReceiver) EventKv(eventName string, kvs map[string]string) { - if n.logger != nil { - n.logger.Output(colog.LDebug, 5, eventName) - } + n.logger.WithCallDepth(5).V(1).Info(eventName) } // EventErr receives a notification of an error if one occurs @@ -42,23 +38,21 @@ func (n *EventReceiver) Timing(eventName string, nanoseconds int64) { // TimingKv receives the time an event took to happen along with optional key/value data func (n *EventReceiver) TimingKv(eventName string, nanoseconds int64, kvs map[string]string) { - if n.logger != nil { - sql := kvs["sql"] - sp := strings.Index(sql, " ") - if sp != -1 { - query := sql[:sp] - if n.s.LogLevel > 1 { - n.logger.Output(colog.LDebug, 6, sql) - } else { - if len(sql) > 50 { - sql = sql[:50] + "..." - } - if query == "SELECT" && n.s.LogLevel > 0 { - n.logger.Output(colog.LDebug, 6, sql) - } else { - n.logger.Output(colog.LDebug, 6, sql) - } - } - } - } + sql := kvs["sql"] + sp := strings.Index(sql, " ") + if sp != -1 { + query := sql[:sp] + if n.s.LogLevel > 1 { + n.logger.WithCallDepth(6).V(1).Info(sql) + } else { + if len(sql) > 50 { + sql = sql[:50] + "..." + } + if query == "SELECT" && n.s.LogLevel > 0 { + n.logger.WithCallDepth(6).V(1).Info(sql) + } else { + n.logger.WithCallDepth(6).V(1).Info(sql) + } + } + } }