Merge pull request #795 from gobuffalo/logger-with-tx-id

feature: log transaction/connection ID to track SQL executions for a request

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

go.mod

@@ -14,15 +14,15 @@ require (
 	github.com/gobuffalo/nulls v0.4.2
 	github.com/gobuffalo/plush/v4 v4.1.16
 	github.com/gobuffalo/validate/v3 v3.3.3
-	github.com/gofrs/uuid v4.3.0+incompatible
+	github.com/gofrs/uuid v4.3.1+incompatible
 	github.com/jackc/pgconn v1.13.0
 	github.com/jackc/pgx/v4 v4.17.2
 	github.com/jmoiron/sqlx v1.3.5
 	github.com/lib/pq v1.10.7
 	github.com/luna-duclos/instrumentedsql v1.1.3
-	github.com/mattn/go-sqlite3 v1.14.15
-	github.com/spf13/cobra v1.5.0
-	github.com/stretchr/testify v1.8.0
-	golang.org/x/sync v0.0.0-20220929204114-8fcdb60fdcc0
+	github.com/mattn/go-sqlite3 v1.14.16
+	github.com/spf13/cobra v1.6.1
+	github.com/stretchr/testify v1.8.1
+	golang.org/x/sync v0.1.0
 	gopkg.in/yaml.v2 v2.4.0
 )

go.sum

@@ -49,13 +49,13 @@ github.com/gobuffalo/validate/v3 v3.3.3 h1:o7wkIGSvZBYBd6ChQoLxkz2y1pfmhbI4jNJYh
 github.com/gobuffalo/validate/v3 v3.3.3/go.mod h1:YC7FsbJ/9hW/VjQdmXPvFqvRis4vrRYFxr69WiNZw6g=
 github.com/gofrs/uuid v4.0.0+incompatible/go.mod h1:b2aQJv3Z4Fp6yNu3cdSllBxTCLRxnplIgP/c0N/04lM=
 github.com/gofrs/uuid v4.2.0+incompatible/go.mod h1:b2aQJv3Z4Fp6yNu3cdSllBxTCLRxnplIgP/c0N/04lM=
-github.com/gofrs/uuid v4.3.0+incompatible h1:CaSVZxm5B+7o45rtab4jC2G37WGYX1zQfuU2i6DSvnc=
-github.com/gofrs/uuid v4.3.0+incompatible/go.mod h1:b2aQJv3Z4Fp6yNu3cdSllBxTCLRxnplIgP/c0N/04lM=
+github.com/gofrs/uuid v4.3.1+incompatible h1:0/KbAdpx3UXAx1kEOWHJeOkpbgRFGHVgv+CFIY7dBJI=
+github.com/gofrs/uuid v4.3.1+incompatible/go.mod h1:b2aQJv3Z4Fp6yNu3cdSllBxTCLRxnplIgP/c0N/04lM=
 github.com/google/renameio v0.1.0/go.mod h1:KWCgfxg9yswjAJkECMjeO8J8rahYeXnNhOm40UhjYkI=
 github.com/gorilla/css v1.0.0 h1:BQqNyPTi50JCFMTw/b67hByjMVXZRwGha6wxVGkeihY=
 github.com/gorilla/css v1.0.0/go.mod h1:Dn721qIggHpt4+EFCcTLTU/vk5ySda2ReITrtgBl60c=
-github.com/inconshreveable/mousetrap v1.0.0 h1:Z8tu5sraLXCXIcARxBp/8cbvlwVa7Z1NHg9XEKhtSvM=
-github.com/inconshreveable/mousetrap v1.0.0/go.mod h1:PxqpIevigyE2G7u3NXJIT2ANytuPF1OarO4DADm73n8=
+github.com/inconshreveable/mousetrap v1.0.1 h1:U3uMjPSQEBMNp1lFxmllqCPM6P5u/Xq7Pgzkat/bFNc=
+github.com/inconshreveable/mousetrap v1.0.1/go.mod h1:vpF70FUmC8bwa3OWnCshd2FqLfsEA9PFc4w1p2J65bw=
 github.com/jackc/chunkreader v1.0.0 h1:4s39bBR8ByfqH+DKm8rQA3E1LHZWB9XWcrz8fqaZbe0=
 github.com/jackc/chunkreader v1.0.0/go.mod h1:RT6O25fNZIuasFJRyZ4R/Y2BbhasbmZXF9QQ7T3kePo=
 github.com/jackc/chunkreader/v2 v2.0.0/go.mod h1:odVSm741yZoC3dpHEUXIqA9tQRhFrgOHwnPIn9lDKlk=
@@ -138,8 +138,9 @@ github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Ky
 github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
 github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/mattn/go-sqlite3 v1.14.6/go.mod h1:NyWgC/yNuGj7Q9rpYnZvas74GogHl5/Z4A/KQRfk6bU=
-github.com/mattn/go-sqlite3 v1.14.15 h1:vfoHhTN1af61xCRSWzFIWzx2YskyMTwHLrExkBOjvxI=
 github.com/mattn/go-sqlite3 v1.14.15/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg=
+github.com/mattn/go-sqlite3 v1.14.16 h1:yOQRA0RpS5PFz/oikGwBEqvAWhWg5ufRz4ETLjwpU1Y=
+github.com/mattn/go-sqlite3 v1.14.16/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg=
 github.com/microcosm-cc/bluemonday v1.0.20 h1:flpzsq4KU3QIYAYGV/szUat7H+GPOXR0B2JU5A1Wp8Y=
 github.com/microcosm-cc/bluemonday v1.0.20/go.mod h1:yfBmMi8mxvaZut3Yytv+jTXRY8mxyjJ0/kQBTElld50=
 github.com/pkg/diff v0.0.0-20210226163009-20ebb0f2a09e/go.mod h1:pJLUxLENpZxwdsKMEsNbx1VGcRFpLqf3715MtcvvzbA=
@@ -169,22 +170,24 @@ github.com/sourcegraph/annotate v0.0.0-20160123013949-f4cad6c6324d h1:yKm7XZV6j9
 github.com/sourcegraph/annotate v0.0.0-20160123013949-f4cad6c6324d/go.mod h1:UdhH50NIW0fCiwBSr0co2m7BnFLdv4fQTgdqdJTHFeE=
 github.com/sourcegraph/syntaxhighlight v0.0.0-20170531221838-bd320f5d308e h1:qpG93cPwA5f7s/ZPBJnGOYQNK/vKsaDaseuKT5Asee8=
 github.com/sourcegraph/syntaxhighlight v0.0.0-20170531221838-bd320f5d308e/go.mod h1:HuIsMU8RRBOtsCgI77wP899iHVBQpCmg4ErYMZB+2IA=
-github.com/spf13/cobra v1.5.0 h1:X+jTBEBqF0bHN+9cSMgmfuvv2VHJ9ezmFNf9Y/XstYU=
-github.com/spf13/cobra v1.5.0/go.mod h1:dWXEIy2H428czQCjInthrTRUg7yKbok+2Qi/yBIJoUM=
+github.com/spf13/cobra v1.6.1 h1:o94oiPyS4KD1mPy2fmcYYHHfCxLqYjJOhGsCHFZtEzA=
+github.com/spf13/cobra v1.6.1/go.mod h1:IOw/AERYS7UzyrGinqmz6HLUo219MORXGxhbaJUqzrY=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.2.0/go.mod h1:qt09Ya8vawLte6SNmTgCsAVtYtaKzEcn8ATUoHMkEqE=
 github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
+github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
-github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk=
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
+github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
+github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
 github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
 github.com/zenazn/goji v0.9.0/go.mod h1:7S9M489iMyHBNxwZnk9/EHS098H4/F6TATF2mIxtB1Q=
 go.uber.org/atomic v1.3.2/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
@@ -227,8 +230,9 @@ golang.org/x/net v0.0.0-20221002022538-bcab6841153b h1:6e93nYa3hNqAvLr0pD4PN1fFS
 golang.org/x/net v0.0.0-20221002022538-bcab6841153b/go.mod h1:YDH+HFinaLZZlnHAfSS6ZXJJ9M9t4Dl22yv3iI2vPwk=
 golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20220722155255-886fb9371eb4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
-golang.org/x/sync v0.0.0-20220929204114-8fcdb60fdcc0 h1:cu5kTvlzcw1Q5S9f5ip1/cpiB4nXvw1XYzFPGgzLUOY=
 golang.org/x/sync v0.0.0-20220929204114-8fcdb60fdcc0/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sync v0.1.0 h1:wsuoTGHzEhffawBOhz5CYhcrV4IdKZbEyZjBMuTp12o=
+golang.org/x/sync v0.1.0/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=

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