added tx/conn ID in the sql logs

connection.go

@@ -5,6 +5,8 @@ import (
 	"database/sql"
 	"errors"
 	"fmt"
+	"math/rand"
+	"strings"
 	"sync/atomic"
 	"time"
 
@@ -63,9 +65,8 @@ func NewConnection(deets *ConnectionDetails) (*Connection, error) {
 	if err != nil {
 		return nil, err
 	}
-	c := &Connection{
-		ID: randx.String(30),
-	}
+	c := &Connection{}
+	c.setID()
 
 	if nc, ok := newConnection[deets.Dialect]; ok {
 		c.Dialect, err = nc(deets)
@@ -156,15 +157,15 @@ func (c *Connection) Transaction(fn func(tx *Connection) error) error {
 	return c.Dialect.Lock(func() (err error) {
 		var dberr error
 
-		log(logging.SQL, "--- BEGIN Transaction ---")
 		cn, err := c.NewTransaction()
 		if err != nil {
 			return err
 		}
+		txlog(logging.SQL, cn, "BEGIN Transaction ---")
 
 		defer func() {
 			if ex := recover(); ex != nil {
-				log(logging.SQL, "--- ROLLBACK Transaction (inner function panic) ---")
+				txlog(logging.SQL, cn, "ROLLBACK Transaction (inner function panic) ---")
 				dberr = cn.TX.Rollback()
 				if dberr != nil {
 					err = fmt.Errorf("database error while inner panic rollback: %w", dberr)
@@ -175,10 +176,10 @@ func (c *Connection) Transaction(fn func(tx *Connection) error) error {
 
 		err = fn(cn)
 		if err != nil {
-			log(logging.SQL, "--- ROLLBACK Transaction ---")
+			txlog(logging.SQL, cn, "ROLLBACK Transaction ---")
 			dberr = cn.TX.Rollback()
 		} else {
-			log(logging.SQL, "--- END Transaction ---")
+			txlog(logging.SQL, cn, "END Transaction ---")
 			dberr = cn.TX.Commit()
 		}
 
@@ -194,11 +195,14 @@ func (c *Connection) Transaction(fn func(tx *Connection) error) error {
 // Rollback will open a new transaction and automatically rollback that transaction
 // when the inner function returns, regardless. This can be useful for tests, etc...
 func (c *Connection) Rollback(fn func(tx *Connection)) error {
+	// TODO: the name of the method could be changed to express it better.
 	cn, err := c.NewTransaction()
 	if err != nil {
 		return err
 	}
+	txlog(logging.SQL, cn, "BEGIN Transaction for Rollback ---")
 	fn(cn)
+	txlog(logging.SQL, cn, "ROLLBACK Transaction as planned ---")
 	return cn.TX.Rollback()
 }
 
@@ -222,11 +226,11 @@ func (c *Connection) NewTransactionContextOptions(ctx context.Context, options *
 		}
 
 		cn = &Connection{
-			ID:      randx.String(30),
 			Store:   contextStore{store: tx, ctx: ctx},
 			Dialect: c.Dialect,
 			TX:      tx,
 		}
+		cn.setID()
 	} else {
 		cn = c
 	}
@@ -244,12 +248,18 @@ func (c *Connection) WithContext(ctx context.Context) *Connection {
 }
 
 func (c *Connection) copy() *Connection {
-	return &Connection{
-		ID:      randx.String(30),
+	// TODO: checkme. it copies and creates a new Connection (and a new ID)
+	// with the same TX which could make confusions and complexity in usage.
+	// related PRs: #72/#73, #79/#80, and #497
+
+	cn := &Connection{
 		Store:   c.Store,
 		Dialect: c.Dialect,
 		TX:      c.TX,
 	}
+	cn.setID(c.ID) // ID of the source as a seed
+
+	return cn
 }
 
 // Q creates a new "empty" query for the current connection.
@@ -282,3 +292,32 @@ func (c *Connection) timeFunc(name string, fn func() error) error {
 	}
 	return nil
 }
+
+// setID sets a unique ID for a Connection in a specific format indicating the
+// Connection type, TX.ID, and optionally a copy ID. It makes it easy to trace
+// related queries for a single request.
+//
+//  examples: "conn-7881415437117811350", "tx-4924907692359316530", "tx-831769923571164863-ytzxZa"
+func (c *Connection) setID(id ...string) {
+	if len(id) == 1 {
+		idElems := strings.Split(id[0], "-")
+		l := 2
+		if len(idElems) < 2 {
+			l = len(idElems)
+		}
+		prefix := strings.Join(idElems[0:l], "-")
+		body := randx.String(6)
+
+		c.ID = fmt.Sprintf("%s-%s", prefix, body)
+	} else {
+		prefix := "conn"
+		body := rand.Int()
+
+		if c.TX != nil {
+			prefix = "tx"
+			body = c.TX.ID
+		}
+
+		c.ID = fmt.Sprintf("%s-%d", prefix, body)
+	}
+}

dialect_cockroach.go

@@ -81,7 +81,7 @@ func (p *cockroach) Create(s store, model *Model, cols columns.Columns) error {
 		} else {
 			query = fmt.Sprintf("INSERT INTO %s DEFAULT VALUES returning %s", p.Quote(model.TableName()), model.IDField())
 		}
-		log(logging.SQL, query, model.Value)
+		txlog(logging.SQL, s, query, model.Value)
 		stmt, err := s.PrepareNamed(query)
 		if err != nil {
 			return err

dialect_common.go

@@ -53,7 +53,7 @@ func genericCreate(s store, model *Model, cols columns.Columns, quoter quotable)
 		cols.Remove(model.IDField())
 		w := cols.Writeable()
 		query := fmt.Sprintf("INSERT INTO %s (%s) VALUES (%s)", quoter.Quote(model.TableName()), w.QuotedString(quoter), w.SymbolizedString())
-		log(logging.SQL, query, model.Value)
+		txlog(logging.SQL, s, query, model.Value)
 		res, err := s.NamedExec(query, model.Value)
 		if err != nil {
 			return err
@@ -81,7 +81,7 @@ func genericCreate(s store, model *Model, cols columns.Columns, quoter quotable)
 		w := cols.Writeable()
 		w.Add(model.IDField())
 		query := fmt.Sprintf("INSERT INTO %s (%s) VALUES (%s)", quoter.Quote(model.TableName()), w.QuotedString(quoter), w.SymbolizedString())
-		log(logging.SQL, query, model.Value)
+		txlog(logging.SQL, s, query, model.Value)
 		stmt, err := s.PrepareNamed(query)
 		if err != nil {
 			return err
@@ -103,7 +103,7 @@ func genericCreate(s store, model *Model, cols columns.Columns, quoter quotable)
 
 func genericUpdate(s store, model *Model, cols columns.Columns, quoter quotable) error {
 	stmt := fmt.Sprintf("UPDATE %s AS %s SET %s WHERE %s", quoter.Quote(model.TableName()), model.Alias(), cols.Writeable().QuotedUpdateString(quoter), model.WhereNamedID())
-	log(logging.SQL, stmt, model.ID())
+	txlog(logging.SQL, s, stmt, model.ID())
 	_, err := s.NamedExec(stmt, model.Value)
 	if err != nil {
 		return err
@@ -153,14 +153,14 @@ func genericDelete(s store, model *Model, query Query) error {
 }
 
 func genericExec(s store, stmt string, args ...interface{}) (sql.Result, error) {
-	log(logging.SQL, stmt, args...)
+	txlog(logging.SQL, s, stmt, args...)
 	res, err := s.Exec(stmt, args...)
 	return res, err
 }
 
 func genericSelectOne(s store, model *Model, query Query) error {
 	sqlQuery, args := query.ToSQL(model)
-	log(logging.SQL, sqlQuery, args...)
+	txlog(logging.SQL, query.Connection, sqlQuery, args...)
 	err := s.Get(model.Value, sqlQuery, args...)
 	if err != nil {
 		return err
@@ -170,7 +170,7 @@ func genericSelectOne(s store, model *Model, query Query) error {
 
 func genericSelectMany(s store, models *Model, query Query) error {
 	sqlQuery, args := query.ToSQL(models)
-	log(logging.SQL, sqlQuery, args...)
+	txlog(logging.SQL, query.Connection, sqlQuery, args...)
 	err := s.Select(models.Value, sqlQuery, args...)
 	if err != nil {
 		return err

dialect_postgresql.go

@@ -65,7 +65,7 @@ func (p *postgresql) Create(s store, model *Model, cols columns.Columns) error {
 		} else {
 			query = fmt.Sprintf("INSERT INTO %s DEFAULT VALUES returning %s", p.Quote(model.TableName()), model.IDField())
 		}
-		log(logging.SQL, query, model.Value)
+		txlog(logging.SQL, s, query, model.Value)
 		stmt, err := s.PrepareNamed(query)
 		if err != nil {
 			return err

dialect_sqlite.go

@@ -87,7 +87,7 @@ func (m *sqlite) Create(s store, model *Model, cols columns.Columns) error {
 			} else {
 				query = fmt.Sprintf("INSERT INTO %s DEFAULT VALUES", m.Quote(model.TableName()))
 			}
-			log(logging.SQL, query, model.Value)
+			txlog(logging.SQL, s, query, model.Value)
 			res, err := s.NamedExec(query, model.Value)
 			if err != nil {
 				return err

executors.go

@@ -30,7 +30,7 @@ func (q *Query) Exec() error {
 			return fmt.Errorf("empty query")
 		}
 
-		log(logging.SQL, sql, args...)
+		txlog(logging.SQL, q.Connection, sql, args...)
 		_, err := q.Connection.Store.Exec(sql, args...)
 		return err
 	})
@@ -46,7 +46,7 @@ func (q *Query) ExecWithCount() (int, error) {
 			return fmt.Errorf("empty query")
 		}
 
-		log(logging.SQL, sql, args...)
+		txlog(logging.SQL, q.Connection, sql, args...)
 		result, err := q.Connection.Store.Exec(sql, args...)
 		if err != nil {
 			return err

finders.go

@@ -325,7 +325,7 @@ func (q *Query) Exists(model interface{}) (bool, error) {
 		}
 
 		existsQuery := fmt.Sprintf("SELECT EXISTS (%s)", query)
-		log(logging.SQL, existsQuery, args...)
+		txlog(logging.SQL, q.Connection, existsQuery, args...)
 		return q.Connection.Store.Get(&res, existsQuery, args...)
 	})
 	return res, err
@@ -371,7 +371,7 @@ func (q Query) CountByField(model interface{}, field string) (int, error) {
 		}
 
 		countQuery := fmt.Sprintf("SELECT COUNT(%s) AS row_count FROM (%s) a", field, query)
-		log(logging.SQL, countQuery, args...)
+		txlog(logging.SQL, q.Connection, countQuery, args...)
 		return q.Connection.Store.Get(res, countQuery, args...)
 	})
 	return res.Count, err

logger.go

@@ -20,9 +20,18 @@ func SetLogger(logger func(level logging.Level, s string, args ...interface{}))
 	log = logger
 }
 
+// SetLogger overrides the default logger.
+func SetTxLogger(logger func(level logging.Level, anon interface{}, s string, args ...interface{})) {
+	txlog = logger
+}
+
 var defaultStdLogger = stdlog.New(os.Stderr, "[POP] ", stdlog.LstdFlags)
 
 var log = func(lvl logging.Level, s string, args ...interface{}) {
+	txlog(lvl, nil, s, args...)
+}
+
+var txlog = func(lvl logging.Level, anon interface{}, s string, args ...interface{}) {
 	if !Debug && lvl <= logging.Debug {
 		return
 	}
@@ -41,6 +50,24 @@ var log = func(lvl logging.Level, s string, args ...interface{}) {
 		} else {
 			s = fmt.Sprintf("%s - %s", lvl, s)
 		}
+
+		connID := ""
+		txID := 0
+		switch typed := anon.(type) {
+		case *Connection:
+			connID = typed.ID
+			if typed.TX != nil {
+				txID = typed.TX.ID
+			}
+		case *Tx:
+			txID = typed.ID
+		case store:
+			tx, err := typed.Transaction()
+			if err == nil {
+				txID = tx.ID
+			}
+		}
+		s = fmt.Sprintf("%s (conn=%v, tx=%v)", s, connID, txID)
 	} else {
 		s = fmt.Sprintf(s, args...)
 		s = fmt.Sprintf("%s - %s", lvl, s)

preload_associations.go

@@ -460,13 +460,13 @@ func preloadManyToMany(tx *Connection, asoc *AssociationMetaInfo, mmi *ModelMeta
 	sql := fmt.Sprintf("SELECT %s, %s FROM %s WHERE %s in (?)", modelAssociationName, assocFkName, manyToManyTableName, modelAssociationName)
 	sql, args, _ := sqlx.In(sql, ids)
 	sql = tx.Dialect.TranslateSQL(sql)
-	log(logging.SQL, sql, args...)
 
 	cn, err := tx.Store.Transaction()
 	if err != nil {
 		return err
 	}
 
+	txlog(logging.SQL, cn, sql, args...)
 	rows, err := cn.Queryx(sql, args...)
 	if err != nil {
 		return err